Enable contextual debug logging for integration tests

common/api-review/firestore-lite.api.md

@@ -373,7 +373,7 @@ export function setDoc<AppModelType, DbModelType extends DocumentData>(reference
 export function setDoc<AppModelType, DbModelType extends DocumentData>(reference: DocumentReference<AppModelType, DbModelType>, data: PartialWithFieldValue<AppModelType>, options: SetOptions): Promise<void>;
 
 // @public
-export function setLogLevel(logLevel: LogLevel): void;
+export function setLogLevel(logLevel: LogLevel, includeContext?: number): void;
 
 // @public
 export type SetOptions = {

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<void>;
 
 // @public
-export function setLogLevel(logLevel: LogLevel): void;
+export function setLogLevel(logLevel: LogLevel, includeContext?: number): void;
 
 // @public
 export type SetOptions = {

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,

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
+    );
+  }
 }

packages/firestore/src/remote/remote_store.ts

@@ -47,7 +47,7 @@
 } from './persistent_stream';
 import { RemoteSyncer } from './remote_syncer';
 import { isPermanentWriteError } from './rpc_error';
 import {
   DocumentWatchChange,
   ExistenceFilterChange,
   WatchChange,
@@ -55,6 +55,7 @@
   WatchTargetChange,
   WatchTargetChangeState
 } from './watch_change';
+import { canonifyTarget } from '../core/target';
 
 const LOG_TAG = 'RemoteStore';
 
@@ -331,6 +332,11 @@
   remoteStoreImpl: RemoteStoreImpl,
   targetData: TargetData
 ): void {
+  logDebug(
+    `sendWatchRequest (target id: ${
+      targetData.targetId
+    }) (target: ${canonifyTarget(targetData.target)})`
+  );
   remoteStoreImpl.watchChangeAggregator!.recordPendingTargetRequest(
     targetData.targetId
   );
@@ -357,6 +363,7 @@
   remoteStoreImpl: RemoteStoreImpl,
   targetId: TargetId
 ): void {
+  logDebug(`sendUnwatchRequest (target id: ${targetId})`);
   remoteStoreImpl.watchChangeAggregator!.recordPendingTargetRequest(targetId);
   ensureWatchStream(remoteStoreImpl).unwatch(targetId);
 }

packages/firestore/src/util/log.ts

@@ -15,14 +15,20 @@
  * 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<{ level: LogLevel; now: string; args: unknown[] }>
+  | undefined;
 
 // Helper methods are needed because variables can't be exported as read/write
 export function getLogLevel(): LogLevel {
@@ -41,20 +47,41 @@
  *     <li>`error` to log errors only.</li>
  *     <li><code>`silent` to turn off logging.</li>
  *   </ul>
+ * @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<{
+      level: LogLevel;
+      now: string;
+      args: unknown[];
+    }>(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 +91,7 @@
  * @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 +112,159 @@
     }
   }
 }
+
+export class LogBuffer<T> {
+  private _buffer: T[];
+  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(v: T): void {
+    this._buffer.push(v);
+
+    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(): T | undefined {
+    return this._buffer[0];
+  }
+
+  /**
+   * Iterate from oldest to newest.
+   */
+  [Symbol.iterator](): Iterator<T> {
+    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<T> => {
+        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
+  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;
+  }
+
+  // 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})`
+    );
+  }
+}