From badc1771932650dcde288580b70dd324cc20c594 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Fri, 9 May 2025 10:13:11 -0600 Subject: [PATCH 01/10] Enable contextual debug logging for integration tests --- packages/firestore/src/util/log.ts | 191 +++++++++++++++++- .../test/integration/util/firebase_export.ts | 5 +- 2 files changed, 190 insertions(+), 6 deletions(-) diff --git a/packages/firestore/src/util/log.ts b/packages/firestore/src/util/log.ts index cbdbad38ecf..70f36ed2558 100644 --- a/packages/firestore/src/util/log.ts +++ b/packages/firestore/src/util/log.ts @@ -15,14 +15,18 @@ * limitations under the License. */ -import { Logger, LogLevel, LogLevelString } from '@firebase/logger'; +import { Logger, LogHandler, LogLevel, LogLevelString } from '@firebase/logger'; import { SDK_VERSION } from '../core/version'; import { formatJSON } from '../platform/format_json'; +import { generateUniqueDebugId } from './debug_uid'; + export { LogLevel, LogLevelString }; const logClient = new Logger('@firebase/firestore'); +const defaultLogHandler = logClient.logHandler; +let logBuffer: LogBuffer | undefined; // Helper methods are needed because variables can't be exported as read/write export function getLogLevel(): LogLevel { @@ -41,20 +45,37 @@ export function getLogLevel(): LogLevel { *
  • `error` to log errors only.
  • *
  • `silent` to turn off logging.
  • * + * @param includeContext - If set to a positive value, the logger will buffer + * all log messages (of all log levels) and log the most recent messages + * when a message of `logLevel` is seen. This is useful if you want to get + * debug logging from the SDK leading up to a warning or error, but do not + * always want debug log verbosity. This param specifies how many messages + * to buffer. */ -export function setLogLevel(logLevel: LogLevelString): void { +export function setLogLevel( + logLevel: LogLevelString, + includeContext: number = 0 +): void { logClient.setLogLevel(logLevel); + + if (includeContext > 0) { + logBuffer = new LogBuffer(includeContext); + logClient.logHandler = bufferingLogHandler; + } else { + logBuffer = undefined; + logClient.logHandler = defaultLogHandler; + } } export function logDebug(msg: string, ...obj: unknown[]): void { - if (logClient.logLevel <= LogLevel.DEBUG) { + if (logBuffer || logClient.logLevel <= LogLevel.DEBUG) { const args = obj.map(argToString); logClient.debug(`Firestore (${SDK_VERSION}): ${msg}`, ...args); } } export function logError(msg: string, ...obj: unknown[]): void { - if (logClient.logLevel <= LogLevel.ERROR) { + if (logBuffer || logClient.logLevel <= LogLevel.ERROR) { const args = obj.map(argToString); logClient.error(`Firestore (${SDK_VERSION}): ${msg}`, ...args); } @@ -64,7 +85,7 @@ export function logError(msg: string, ...obj: unknown[]): void { * @internal */ export function logWarn(msg: string, ...obj: unknown[]): void { - if (logClient.logLevel <= LogLevel.WARN) { + if (logBuffer || logClient.logLevel <= LogLevel.WARN) { const args = obj.map(argToString); logClient.warn(`Firestore (${SDK_VERSION}): ${msg}`, ...args); } @@ -85,3 +106,163 @@ function argToString(obj: unknown): string | unknown { } } } + +class LogBuffer { + private _buffer: Array<{ level: LogLevel; now: string; args: unknown[] }>; + private _numTruncated: number = 0; + + constructor(readonly bufferSize: number) { + this._buffer = []; + this._numTruncated = 0; + } + + /** + * Clear the log buffer + */ + clear(): void { + this._buffer = []; + this._numTruncated = 0; + } + + /** + * Add a new log message to the buffer. If the buffer will exceed + * the allocated buffer size, then remove the oldest message from + * the buffer. + * @param level + * @param now + * @param args + */ + add(level: LogLevel, now: string, args: unknown[]): void { + this._buffer.push({ + level, + now, + args + }); + + if (this._buffer.length > this.bufferSize) { + // remove the first (oldest) element + this._buffer.shift(); + this._numTruncated++; + } + } + + /** + * Returns the number of old log messages that have been + * truncated from the log to maintain buffer size. + */ + get numTruncated(): number { + return this._numTruncated; + } + + get first(): { level: LogLevel; now: string; args: unknown[] } | undefined { + return this._buffer[0]; + } + + /** + * Iterate from oldest to newest. + */ + [Symbol.iterator](): Iterator<{ + level: LogLevel; + now: string; + args: unknown[]; + }> { + let currentIndex = 0; + // Create a snapshot of the buffer for iteration. + // This ensures that if the buffer is modified while iterating (e.g., by adding new logs), + // the iterator will continue to iterate over the state of the buffer as it was when iteration began. + // It also means you iterate from the oldest to the newest log. + const bufferSnapshot = [...this._buffer]; + + return { + next: (): IteratorResult<{ + level: LogLevel; + now: string; + args: unknown[]; + }> => { + if (currentIndex < bufferSnapshot.length) { + return { value: bufferSnapshot[currentIndex++], done: false }; + } else { + return { value: undefined, done: true }; + } + } + }; + } +} + +/** + * By default, `console.debug` is not displayed in the developer console (in + * chrome). To avoid forcing users to have to opt-in to these logs twice + * (i.e. once for firebase, and once in the console), we are sending `DEBUG` + * logs to the `console.log` function. + */ +const ConsoleMethod = { + [LogLevel.DEBUG]: 'log', + [LogLevel.VERBOSE]: 'log', + [LogLevel.INFO]: 'info', + [LogLevel.WARN]: 'warn', + [LogLevel.ERROR]: 'error' +}; + +/** + * The default log handler will forward DEBUG, VERBOSE, INFO, WARN, and ERROR + * messages on to their corresponding console counterparts (if the log method + * is supported by the current log level) + */ +const bufferingLogHandler: LogHandler = (instance, logType, ...args): void => { + const now = new Date().toISOString(); + + // Fail-safe. This is never expected to be true, but if it is, + // it's not important enough to throw. + if (!logBuffer) { + defaultLogHandler(instance, logType, args); + return; + } + + // Buffer any messages less than the current logLevel + if (logType < instance.logLevel) { + logBuffer!.add(logType, now, args); + return; + } + + // create identifier that associates all of the associated + // context messages with the log message that caused the + // flush of the logBuffer + const id = generateUniqueDebugId(); + + // Optionally write a log message stating if any log messages + // were skipped. + if (logBuffer.first) { + writeLog(instance, id, LogLevel.INFO, logBuffer.first.now, [ + `... ${logBuffer.numTruncated} log messages skipped ...` + ]); + } + + // If here, write the log buffer contents as context + for (const logInfo of logBuffer) { + writeLog(instance, id, logInfo.level, logInfo.now, logInfo.args); + } + logBuffer.clear(); + + // Now write the target log message. + writeLog(instance, id, logType, now, args); +}; + +function writeLog( + instance: Logger, + id: string, + logType: LogLevel, + now: string, + args: unknown[] +): void { + const method = ConsoleMethod[logType as keyof typeof ConsoleMethod]; + if (method) { + console[method as 'log' | 'info' | 'warn' | 'error']( + `[${now}] (context: ${id}) ${instance.name}:`, + ...args + ); + } else { + throw new Error( + `Attempted to log a message with an invalid logType (value: ${logType})` + ); + } +} diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index f58b3ce045b..0f601bd7b26 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -22,13 +22,16 @@ import { FirebaseApp, initializeApp } from '@firebase/app'; -import { Firestore, initializeFirestore } from '../../../src'; +import { Firestore, initializeFirestore, setLogLevel } 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; +// enable contextual debug logging +setLogLevel('error', 100); + export function newTestApp(projectId: string, appName?: string): FirebaseApp { if (appName === undefined) { appName = 'test-app-' + appCount++; From d137ce622bd1df383f3849462c1bf08184e72948 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Mon, 12 May 2025 09:49:37 -0600 Subject: [PATCH 02/10] Spy on webchannel for test logging --- packages/firestore/src/util/log.ts | 38 ++++---- .../test/integration/util/firebase_export.ts | 91 ++++++++++++++++++- 2 files changed, 106 insertions(+), 23 deletions(-) diff --git a/packages/firestore/src/util/log.ts b/packages/firestore/src/util/log.ts index 70f36ed2558..91d4a224809 100644 --- a/packages/firestore/src/util/log.ts +++ b/packages/firestore/src/util/log.ts @@ -26,7 +26,9 @@ export { LogLevel, LogLevelString }; const logClient = new Logger('@firebase/firestore'); const defaultLogHandler = logClient.logHandler; -let logBuffer: LogBuffer | undefined; +let logBuffer: + | LogBuffer<{ level: LogLevel; now: string; args: unknown[] }> + | undefined; // Helper methods are needed because variables can't be exported as read/write export function getLogLevel(): LogLevel { @@ -59,7 +61,11 @@ export function setLogLevel( logClient.setLogLevel(logLevel); if (includeContext > 0) { - logBuffer = new LogBuffer(includeContext); + logBuffer = new LogBuffer<{ + level: LogLevel; + now: string; + args: unknown[]; + }>(includeContext); logClient.logHandler = bufferingLogHandler; } else { logBuffer = undefined; @@ -107,8 +113,8 @@ function argToString(obj: unknown): string | unknown { } } -class LogBuffer { - private _buffer: Array<{ level: LogLevel; now: string; args: unknown[] }>; +export class LogBuffer { + private _buffer: T[]; private _numTruncated: number = 0; constructor(readonly bufferSize: number) { @@ -132,12 +138,8 @@ class LogBuffer { * @param now * @param args */ - add(level: LogLevel, now: string, args: unknown[]): void { - this._buffer.push({ - level, - now, - args - }); + add(v: T): void { + this._buffer.push(v); if (this._buffer.length > this.bufferSize) { // remove the first (oldest) element @@ -154,18 +156,14 @@ class LogBuffer { return this._numTruncated; } - get first(): { level: LogLevel; now: string; args: unknown[] } | undefined { + get first(): T | undefined { return this._buffer[0]; } /** * Iterate from oldest to newest. */ - [Symbol.iterator](): Iterator<{ - level: LogLevel; - now: string; - args: unknown[]; - }> { + [Symbol.iterator](): Iterator { let currentIndex = 0; // Create a snapshot of the buffer for iteration. // This ensures that if the buffer is modified while iterating (e.g., by adding new logs), @@ -174,11 +172,7 @@ class LogBuffer { const bufferSnapshot = [...this._buffer]; return { - next: (): IteratorResult<{ - level: LogLevel; - now: string; - args: unknown[]; - }> => { + next: (): IteratorResult => { if (currentIndex < bufferSnapshot.length) { return { value: bufferSnapshot[currentIndex++], done: false }; } else { @@ -220,7 +214,7 @@ const bufferingLogHandler: LogHandler = (instance, logType, ...args): void => { // Buffer any messages less than the current logLevel if (logType < instance.logLevel) { - logBuffer!.add(logType, now, args); + logBuffer!.add({ level: logType, now, args }); return; } diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index 0f601bd7b26..d99aa506a78 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -24,13 +24,102 @@ import { FirebaseApp, initializeApp } from '@firebase/app'; import { Firestore, initializeFirestore, setLogLevel } from '../../../src'; import { PrivateSettings } from '../../../src/lite-api/settings'; +import { logDebug } from '../../../src/util/log'; // 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; +const originalFetch = globalThis.fetch; + +/** + * A class that acts as a spy for a ReadableStream. + * It logs the content of the input stream as it's read and then pipes it through. + */ +class ReadableStreamSpy { + private inputReadableStream: ReadableStream; + private spyTransformStream: TransformStream; + private spiedReadableStream: ReadableStream; + + private readonly decoder = new TextDecoder(); + + /** + * Creates an instance of ReadableStreamSpy. + * @param inputReadableStream The ReadableStream to spy on. + */ + constructor(inputReadableStream: ReadableStream) { + if (!(inputReadableStream instanceof ReadableStream)) { + throw new Error('Input must be a ReadableStream.'); + } + + this.inputReadableStream = inputReadableStream; + + // Create a TransformStream that logs data + this.spyTransformStream = new TransformStream({ + transform: ( + chunk: Uint8Array, + controller: TransformStreamDefaultController + ) => { + // @ts-ignore + logDebug(this.decoder.decode(chunk)); + + controller.enqueue(chunk); // Pass the chunk along + }, + flush: (controller: TransformStreamDefaultController) => { + // Any cleanup or final actions if needed + } + }); + + // Pipe the input stream through the spy transform stream + this.spiedReadableStream = this.inputReadableStream.pipeThrough( + this.spyTransformStream + ); + } + + /** + * Gets the spied-on ReadableStream. + * You should read from this stream to observe the logged chunks. + * @returns The ReadableStream with spy functionality. + */ + get readableStream(): ReadableStream { + return this.spiedReadableStream; + } +} + +globalThis.fetch = async function (requestOrUrl, options) { + // @ts-ignore + const url = + typeof requestOrUrl === 'string' ? requestOrUrl : requestOrUrl.url; + + logDebug(`FETCH FOR ${url}`); + + if ( + url.startsWith( + 'https://firestore.googleapis.com/google.firestore.v1.Firestore/Listen/channel' + ) + ) { + const response = await originalFetch(requestOrUrl, options); + + if (response.body) { + const spy = new ReadableStreamSpy(response.body); + + return Promise.resolve( + new Response(spy.readableStream, { + headers: response.headers, + status: response.status, + statusText: response.statusText + }) + ); + } + + return Promise.resolve(response); + } + + return originalFetch(requestOrUrl, options); +}; + // enable contextual debug logging -setLogLevel('error', 100); +setLogLevel('error', 200); export function newTestApp(projectId: string, appName?: string): FirebaseApp { if (appName === undefined) { From c870d73a24bc896d811da0117839dd2679e856de Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Mon, 12 May 2025 09:59:33 -0600 Subject: [PATCH 03/10] fix --- .../firestore/test/integration/util/firebase_export.ts | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index d99aa506a78..2e814a0e912 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -87,9 +87,12 @@ class ReadableStreamSpy { } globalThis.fetch = async function (requestOrUrl, options) { - // @ts-ignore const url = - typeof requestOrUrl === 'string' ? requestOrUrl : requestOrUrl.url; + typeof requestOrUrl === 'string' + ? requestOrUrl + : requestOrUrl instanceof URL + ? requestOrUrl.toString() + : requestOrUrl.url; logDebug(`FETCH FOR ${url}`); From c91a50f38a361fb3ce75452a4fc20cf8e563ee54 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Mon, 12 May 2025 10:10:26 -0600 Subject: [PATCH 04/10] fetch id for logs --- common/api-review/firestore-lite.api.md | 2 +- common/api-review/firestore.api.md | 2 +- .../test/integration/util/firebase_export.ts | 13 ++++++++----- 3 files changed, 10 insertions(+), 7 deletions(-) diff --git a/common/api-review/firestore-lite.api.md b/common/api-review/firestore-lite.api.md index 4a9ef4c0171..0c9ea405938 100644 --- a/common/api-review/firestore-lite.api.md +++ b/common/api-review/firestore-lite.api.md @@ -373,7 +373,7 @@ export function setDoc(reference export function setDoc(reference: DocumentReference, data: PartialWithFieldValue, options: SetOptions): Promise; // @public -export function setLogLevel(logLevel: LogLevel): void; +export function setLogLevel(logLevel: LogLevel, includeContext?: number): void; // @public export type SetOptions = { diff --git a/common/api-review/firestore.api.md b/common/api-review/firestore.api.md index 34b56b97f21..ebbcd96f861 100644 --- a/common/api-review/firestore.api.md +++ b/common/api-review/firestore.api.md @@ -639,7 +639,7 @@ export function setIndexConfiguration(firestore: Firestore, configuration: Index export function setIndexConfiguration(firestore: Firestore, json: string): Promise; // @public -export function setLogLevel(logLevel: LogLevel): void; +export function setLogLevel(logLevel: LogLevel, includeContext?: number): void; // @public export type SetOptions = { diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index 2e814a0e912..6912c39603e 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -25,6 +25,7 @@ import { FirebaseApp, initializeApp } from '@firebase/app'; import { Firestore, initializeFirestore, setLogLevel } from '../../../src'; import { PrivateSettings } from '../../../src/lite-api/settings'; import { logDebug } from '../../../src/util/log'; +import { generateUniqueDebugId } from '../../../src/util/debug_uid'; // 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. @@ -46,8 +47,9 @@ class ReadableStreamSpy { /** * Creates an instance of ReadableStreamSpy. * @param inputReadableStream The ReadableStream to spy on. + * @param id id for logging */ - constructor(inputReadableStream: ReadableStream) { + constructor(inputReadableStream: ReadableStream, id: string) { if (!(inputReadableStream instanceof ReadableStream)) { throw new Error('Input must be a ReadableStream.'); } @@ -61,7 +63,7 @@ class ReadableStreamSpy { controller: TransformStreamDefaultController ) => { // @ts-ignore - logDebug(this.decoder.decode(chunk)); + logDebug(`(fetch: ${id}) ${this.decoder.decode(chunk)}`); controller.enqueue(chunk); // Pass the chunk along }, @@ -94,8 +96,6 @@ globalThis.fetch = async function (requestOrUrl, options) { ? requestOrUrl.toString() : requestOrUrl.url; - logDebug(`FETCH FOR ${url}`); - if ( url.startsWith( 'https://firestore.googleapis.com/google.firestore.v1.Firestore/Listen/channel' @@ -104,7 +104,10 @@ globalThis.fetch = async function (requestOrUrl, options) { const response = await originalFetch(requestOrUrl, options); if (response.body) { - const spy = new ReadableStreamSpy(response.body); + const id = generateUniqueDebugId(); + logDebug(`(fetch: ${id}) FETCH FOR ${url}`); + + const spy = new ReadableStreamSpy(response.body, id); return Promise.resolve( new Response(spy.readableStream, { From a03b6669ee52428152e3e2cb753f6c3bf1535c41 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Mon, 12 May 2025 12:30:17 -0600 Subject: [PATCH 05/10] add debug logging for watch and unwatch target requests --- packages/firestore/src/remote/remote_store.ts | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/packages/firestore/src/remote/remote_store.ts b/packages/firestore/src/remote/remote_store.ts index 6f8aed0503e..4ca86349bc6 100644 --- a/packages/firestore/src/remote/remote_store.ts +++ b/packages/firestore/src/remote/remote_store.ts @@ -55,6 +55,7 @@ import { WatchTargetChange, WatchTargetChangeState } from './watch_change'; +import { canonifyTarget } from '../core/target'; const LOG_TAG = 'RemoteStore'; @@ -331,6 +332,11 @@ function sendWatchRequest( remoteStoreImpl: RemoteStoreImpl, targetData: TargetData ): void { + logDebug( + `sendWatchRequest (target id: ${ + targetData.targetId + }) (target: ${canonifyTarget(targetData.target)})` + ); remoteStoreImpl.watchChangeAggregator!.recordPendingTargetRequest( targetData.targetId ); @@ -357,6 +363,7 @@ function sendUnwatchRequest( remoteStoreImpl: RemoteStoreImpl, targetId: TargetId ): void { + logDebug(`sendUnwatchRequest (target id: ${targetId})`); remoteStoreImpl.watchChangeAggregator!.recordPendingTargetRequest(targetId); ensureWatchStream(remoteStoreImpl).unwatch(targetId); } From f5d43bf3514a01bed434bcc7e63e835d4ff6322f Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Mon, 12 May 2025 14:49:48 -0600 Subject: [PATCH 06/10] get request body --- packages/firestore/src/util/log.ts | 9 ++- .../test/integration/util/firebase_export.ts | 65 +++++++++++++++---- 2 files changed, 59 insertions(+), 15 deletions(-) diff --git a/packages/firestore/src/util/log.ts b/packages/firestore/src/util/log.ts index 91d4a224809..8da885a9345 100644 --- a/packages/firestore/src/util/log.ts +++ b/packages/firestore/src/util/log.ts @@ -213,7 +213,14 @@ const bufferingLogHandler: LogHandler = (instance, logType, ...args): void => { } // Buffer any messages less than the current logLevel - if (logType < instance.logLevel) { + //if (logType < instance.logLevel) { + let codeFound = false; + args.forEach(v => { + if (typeof v === 'string' && /ca9/.test(v)) { + codeFound = true; + } + }); + if (!codeFound) { logBuffer!.add({ level: logType, now, args }); return; } diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index 6912c39603e..a41b0d422d5 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -49,7 +49,11 @@ class ReadableStreamSpy { * @param inputReadableStream The ReadableStream to spy on. * @param id id for logging */ - constructor(inputReadableStream: ReadableStream, id: string) { + constructor( + type: 'request' | 'response', + inputReadableStream: ReadableStream, + id: string + ) { if (!(inputReadableStream instanceof ReadableStream)) { throw new Error('Input must be a ReadableStream.'); } @@ -63,7 +67,7 @@ class ReadableStreamSpy { controller: TransformStreamDefaultController ) => { // @ts-ignore - logDebug(`(fetch: ${id}) ${this.decoder.decode(chunk)}`); + logDebug(`${type}: (fetch: ${id}) ${this.decoder.decode(chunk)}`); controller.enqueue(chunk); // Pass the chunk along }, @@ -88,26 +92,59 @@ class ReadableStreamSpy { } } +class RequestInfo {} + globalThis.fetch = async function (requestOrUrl, options) { - const url = - typeof requestOrUrl === 'string' - ? requestOrUrl - : requestOrUrl instanceof URL - ? requestOrUrl.toString() - : requestOrUrl.url; + let url = ''; + let verb = 'GET'; + let request = requestOrUrl; + const id = generateUniqueDebugId(); + + if (typeof requestOrUrl === 'string') { + url = requestOrUrl; + } else if (requestOrUrl instanceof URL) { + url = requestOrUrl.toString(); + } else { + url = requestOrUrl.url; + verb = requestOrUrl.method; + if ( + url.startsWith( + 'https://firestore.googleapis.com/google.firestore.v1.Firestore/Listen/channel' + ) + ) { + try { + if (requestOrUrl.body instanceof ReadableStream) { + const requestSpy = new ReadableStreamSpy( + 'request', + requestOrUrl.body, + id + ); + const requestInit: RequestInit = { + body: requestSpy.readableStream, + // @ts-ignore + duplex: 'half' + }; + request = new Request(requestOrUrl, requestInit); + } else { + logDebug(JSON.stringify(requestOrUrl.body)); + } + } catch (e) { + console.log(e); + } + } + } if ( url.startsWith( 'https://firestore.googleapis.com/google.firestore.v1.Firestore/Listen/channel' ) ) { - const response = await originalFetch(requestOrUrl, options); + logDebug(`(fetch: ${id}) FETCH FOR ${verb} ${url}`); - if (response.body) { - const id = generateUniqueDebugId(); - logDebug(`(fetch: ${id}) FETCH FOR ${url}`); + const response = await originalFetch(request, options); - const spy = new ReadableStreamSpy(response.body, id); + if (response.body) { + const spy = new ReadableStreamSpy('response', response.body, id); return Promise.resolve( new Response(spy.readableStream, { @@ -125,7 +162,7 @@ globalThis.fetch = async function (requestOrUrl, options) { }; // enable contextual debug logging -setLogLevel('error', 200); +setLogLevel('error', 400); export function newTestApp(projectId: string, appName?: string): FirebaseApp { if (appName === undefined) { From 71b23379b7fa951dfaa0748a39b0cb05db1be313 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Mon, 12 May 2025 22:22:40 -0600 Subject: [PATCH 07/10] better detection of target error --- packages/firestore/src/util/log.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/firestore/src/util/log.ts b/packages/firestore/src/util/log.ts index 8da885a9345..cb0dc2ef477 100644 --- a/packages/firestore/src/util/log.ts +++ b/packages/firestore/src/util/log.ts @@ -216,7 +216,7 @@ const bufferingLogHandler: LogHandler = (instance, logType, ...args): void => { //if (logType < instance.logLevel) { let codeFound = false; args.forEach(v => { - if (typeof v === 'string' && /ca9/.test(v)) { + if (typeof v === 'string' && /ID:\sca9/.test(v)) { codeFound = true; } }); From 1fb16cf51260d8628db002b25e961c3ac03f40ae Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Tue, 13 May 2025 10:18:15 -0600 Subject: [PATCH 08/10] Better request body logging --- packages/firestore/src/util/log.ts | 3 +- .../test/integration/util/firebase_export.ts | 48 ++++++++----------- 2 files changed, 22 insertions(+), 29 deletions(-) diff --git a/packages/firestore/src/util/log.ts b/packages/firestore/src/util/log.ts index cb0dc2ef477..bdb8dff1044 100644 --- a/packages/firestore/src/util/log.ts +++ b/packages/firestore/src/util/log.ts @@ -213,13 +213,14 @@ const bufferingLogHandler: LogHandler = (instance, logType, ...args): void => { } // Buffer any messages less than the current logLevel - //if (logType < instance.logLevel) { let codeFound = false; args.forEach(v => { if (typeof v === 'string' && /ID:\sca9/.test(v)) { codeFound = true; } }); + + //if (logType < instance.logLevel) { if (!codeFound) { logBuffer!.add({ level: logType, now, args }); return; diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index a41b0d422d5..0f9370ca829 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -24,7 +24,7 @@ import { FirebaseApp, initializeApp } from '@firebase/app'; import { Firestore, initializeFirestore, setLogLevel } from '../../../src'; import { PrivateSettings } from '../../../src/lite-api/settings'; -import { logDebug } from '../../../src/util/log'; +import { logDebug, logError } from '../../../src/util/log'; import { generateUniqueDebugId } from '../../../src/util/debug_uid'; // TODO(dimond): Right now we create a new app and Firestore instance for @@ -92,12 +92,12 @@ class ReadableStreamSpy { } } -class RequestInfo {} - globalThis.fetch = async function (requestOrUrl, options) { let url = ''; let verb = 'GET'; let request = requestOrUrl; + let bodyPromise: Promise = Promise.resolve('none'); + let contentType: string = ''; const id = generateUniqueDebugId(); if (typeof requestOrUrl === 'string') { @@ -107,31 +107,9 @@ globalThis.fetch = async function (requestOrUrl, options) { } else { url = requestOrUrl.url; verb = requestOrUrl.method; - if ( - url.startsWith( - 'https://firestore.googleapis.com/google.firestore.v1.Firestore/Listen/channel' - ) - ) { - try { - if (requestOrUrl.body instanceof ReadableStream) { - const requestSpy = new ReadableStreamSpy( - 'request', - requestOrUrl.body, - id - ); - const requestInit: RequestInit = { - body: requestSpy.readableStream, - // @ts-ignore - duplex: 'half' - }; - request = new Request(requestOrUrl, requestInit); - } else { - logDebug(JSON.stringify(requestOrUrl.body)); - } - } catch (e) { - console.log(e); - } - } + bodyPromise = requestOrUrl.clone().text(); + contentType = requestOrUrl.headers.get('Content-Type') ?? 'empty'; + request = requestOrUrl; } if ( @@ -143,6 +121,20 @@ globalThis.fetch = async function (requestOrUrl, options) { const response = await originalFetch(request, options); + bodyPromise.then(bodyText => { + if (contentType === 'application/x-www-form-urlencoded') { + const decodedData: Record = {}; + + bodyText.split('&').forEach(pair => { + const [key, value] = pair.split('='); + decodedData[key] = decodeURIComponent(value); + }); + logDebug(`(fetch: ${id}) BODY: ${JSON.stringify(decodedData)}`); + } else { + logDebug(`(fetch: ${id}) BODY: ${bodyText}`); + } + }); + if (response.body) { const spy = new ReadableStreamSpy('response', response.body, id); From f062be68bbb06a816416b509cf1bcab70ebb12a0 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Tue, 13 May 2025 10:39:03 -0600 Subject: [PATCH 09/10] Reorder reporters to prevent log message duplication --- config/karma.base.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config/karma.base.js b/config/karma.base.js index 9d92053115f..fdfe0d35907 100644 --- a/config/karma.base.js +++ b/config/karma.base.js @@ -68,7 +68,7 @@ const config = { // test results reporter to use // possible values: 'dots', 'progress' // available reporters: https://npmjs.org/browse/keyword/karma-reporter - reporters: ['mocha', 'coverage-istanbul'], + reporters: ['coverage-istanbul', 'mocha'], // web server port port: 8089, From ae7848f585411e969c555a06202bd053032eacc8 Mon Sep 17 00:00:00 2001 From: Mark Duckworth <1124037+MarkDuckworth@users.noreply.github.com> Date: Wed, 14 May 2025 10:31:49 -0600 Subject: [PATCH 10/10] Explicitly close any unclosed WebChannel instances on terminate --- .../platform/browser/webchannel_connection.ts | 23 +++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/packages/firestore/src/platform/browser/webchannel_connection.ts b/packages/firestore/src/platform/browser/webchannel_connection.ts index 9a69164457e..f5835408c09 100644 --- a/packages/firestore/src/platform/browser/webchannel_connection.ts +++ b/packages/firestore/src/platform/browser/webchannel_connection.ts @@ -59,6 +59,9 @@ export class WebChannelConnection extends RestConnection { private readonly useFetchStreams: boolean; private readonly longPollingOptions: ExperimentalLongPollingOptions; + /** A collection of open WebChannel instances */ + private webChannels: WebChannel[] = []; + constructor(info: DatabaseInfo) { super(info); this.forceLongPolling = info.forceLongPolling; @@ -239,6 +242,7 @@ export class WebChannelConnection extends RestConnection { request ); const channel = webchannelTransport.createWebChannel(url, request); + this.trackWebChannel(channel); // WebChannel supports sending the first message with the handshake - saving // a network round trip. However, it will have to call send in the same @@ -321,6 +325,7 @@ export class WebChannelConnection extends RestConnection { `RPC '${rpcName}' stream ${streamId} transport closed` ); streamBridge.callOnClose(); + this.untrackWebChannel(channel); } }); @@ -427,4 +432,22 @@ export class WebChannelConnection extends RestConnection { }, 0); return streamBridge; } + + /** + * Closes and cleans up any resources associated with the connection. + */ + terminate(): void { + this.webChannels.forEach(webChannel => webChannel.close()); + this.webChannels = []; + } + + trackWebChannel(webChannel: WebChannel): void { + this.webChannels.push(webChannel); + } + + untrackWebChannel(webChannel: WebChannel): void { + this.webChannels = this.webChannels.filter( + instance => instance === webChannel + ); + } }