Log debugger command latency and status (#39107)

Summary:
Pull Request resolved: https://github.com/facebook/react-native/pull/39107

Augments D48466760 to report debugger commands (request/response pairs) through `EventReporter`. With the appropriate backend integration, this can help validate the correctness/completeness of the CDP implementation (in the client, proxy and server) and measure the latency of debugger commands - more accurately, the time between the proxy receiving a command from the client and receiving the corresponding response from the server.

Most of the new logic here is in the `DeviceEventReporter` class, which is responsible for associating responses with requests. Requests are kept in a buffer with a 10s TTL which serves as a timeout in case of an unresponsive server.

Changelog: [Internal]

Reviewed By: huntie

Differential Revision: D48480372

fbshipit-source-id: 55360a14bbea05ef8ad1622e0d54f18b47483809

flow-typed/npm/@isaacs/ttlcache_1.x.x.js

@@ -0,0 +1,227 @@
+/**
+ * @flow strict-local
+ * @format
+ */
+
+declare module '@isaacs/ttlcache' {
+  declare export default class TTLCache<K, V> implements Iterable<[K, V]> {
+    constructor(options?: TTLCache$Options<K, V>): void;
+
+    ttl: number;
+    max: number;
+    updateAgeOnGet: boolean;
+    checkAgeOnGet: boolean;
+    noUpdateTTL: boolean;
+    noDisposeOnSet: boolean;
+
+    /**
+     * The total number of items held in the cache at the current moment.
+     */
+    +size: number;
+
+    /**
+     * Add a value to the cache.
+     */
+    set(key: K, value: V, options?: TTLCache$SetOptions): this;
+
+    /**
+     * Return a value from the cache.
+     * If the key is not found, `get()` will return `undefined`.
+     * This can be confusing when setting values specifically to `undefined`,
+     * as in `cache.set(key, undefined)`. Use `cache.has()` to determine
+     * whether a key is present in the cache at all.
+     */
+    get<T: V = V>(key: K, options?: TTLCache$GetOptions): T | void;
+
+    /**
+     * Check if a key is in the cache.
+     * Will return false if the item is stale, even though it is technically
+     * in the cache.
+     */
+    has(key: K): boolean;
+
+    /**
+     * Deletes a key out of the cache.
+     * Returns true if the key was deleted, false otherwise.
+     */
+    delete(key: K): boolean;
+
+    /**
+     * Clear the cache entirely, throwing away all values.
+     */
+    clear(): void;
+
+    /**
+     * Delete any stale entries. Returns true if anything was removed, false
+     * otherwise.
+     */
+    purgeStale(): boolean;
+
+    /**
+     * Return the remaining time before an item expires.
+     * Returns 0 if the item is not found in the cache or is already expired.
+     */
+    getRemainingTTL(key: K): number;
+
+    /**
+     * Set the ttl explicitly to a value, defaulting to the TTL set on the ctor
+     */
+    setTTL(key: K, ttl?: number): void;
+
+    /**
+     * Return a generator yielding `[key, value]` pairs, from soonest expiring
+     * to latest expiring. (Items expiring at the same time are walked in insertion order.)
+     */
+    entries(): Generator<[K, V], void, void>;
+
+    /**
+     * Return a generator yielding the keys in the cache,
+     * from soonest expiring to latest expiring.
+     */
+    keys(): Generator<K, void, void>;
+
+    /**
+     * Return a generator yielding the values in the cache,
+     * from soonest expiring to latest expiring.
+     */
+    values(): Generator<V, void, void>;
+
+    /**
+     * Iterating over the cache itself yields the same results as
+     * `cache.entries()`
+     */
+    @@iterator(): Iterator<[K, V]>;
+
+    /**
+     * Cancel the timer and stop automatically expiring entries.
+     * This allows the process to gracefully exit where Timer.unref()
+     * is not available.
+     */
+    cancelTimer(): void;
+  }
+
+  declare type TTLCache$DisposeReason = 'evict' | 'set' | 'delete' | 'stale';
+
+  declare type TTLCache$Disposer<K, V> = (
+    value: V,
+    key: K,
+    reason: TTLCache$DisposeReason,
+  ) => void;
+
+  declare type TTLCache$TTLOptions = {
+    /**
+     * Max time in milliseconds for items to live in cache before they are
+     * considered stale.  Note that stale items are NOT preemptively removed
+     * by default, and MAY live in the cache, contributing to max,
+     * long after they have expired.
+     *
+     * Must be an integer number of ms, or Infinity.  Defaults to `undefined`,
+     * meaning that a TTL must be set explicitly for each set()
+     */
+    ttl?: number,
+
+    /**
+     * Boolean flag to tell the cache to not update the TTL when
+     * setting a new value for an existing key (ie, when updating a value
+     * rather than inserting a new value).  Note that the TTL value is
+     * _always_ set when adding a new entry into the cache.
+     *
+     * @default false
+     */
+    noUpdateTTL?: boolean,
+  };
+
+  declare type TTLCache$Options<K, V> = {
+    /**
+     * The number of items to keep.
+     *
+     * @default Infinity
+     */
+    max?: number,
+
+    /**
+     * Update the age of items on cache.get(), renewing their TTL
+     *
+     * @default false
+     */
+    updateAgeOnGet?: boolean,
+
+    /**
+     * In the event that an item's expiration timer hasn't yet fired,
+     * and an attempt is made to get() it, then return undefined and
+     * delete it, rather than returning the cached value.
+     *
+     * By default, items are only expired when their timer fires, so there's
+     * a bit of a "best effort" expiration, and the cache will return a value
+     * if it has one, even if it's technically stale.
+     *
+     * @default false
+     */
+    checkAgeOnGet?: boolean,
+
+    /**
+     * Do not call dispose() function when overwriting a key with a new value
+     *
+     * @default false
+     */
+    noDisposeOnSet?: boolean,
+
+    /**
+     * Function that is called on items when they are dropped from the cache.
+     * This can be handy if you want to close file descriptors or do other
+     * cleanup tasks when items are no longer accessible. Called with `key,
+     * value`.  It's called before actually removing the item from the
+     * internal cache, so it is *NOT* safe to re-add them.
+     * Use `disposeAfter` if you wish to dispose items after they have been
+     * full removed, when it is safe to add them back to the cache.
+     */
+    dispose?: TTLCache$Disposer<K, V>,
+    ...TTLCache$TTLOptions,
+  };
+
+  declare type TTLCache$SetOptions = {
+    /**
+     * Do not call dispose() function when overwriting a key with a new value
+     * Overrides the value set in the constructor.
+     */
+    noDisposeOnSet?: boolean,
+
+    /**
+     * Do not update the TTL when overwriting an existing item.
+     */
+    noUpdateTTL?: boolean,
+
+    /**
+     * Override the default TTL for this one set() operation.
+     * Required if a TTL was not set in the constructor options.
+     */
+    ttl?: number,
+  };
+
+  declare type TTLCache$GetOptions = {
+    /**
+     * Update the age of items on cache.get(), renewing their TTL
+     *
+     * @default false
+     */
+    updateAgeOnGet?: boolean,
+
+    /**
+     * In the event that an item's expiration timer hasn't yet fired,
+     * and an attempt is made to get() it, then return undefined and
+     * delete it, rather than returning the cached value.
+     *
+     * By default, items are only expired when their timer fires, so there's
+     * a bit of a "best effort" expiration, and the cache will return a value
+     * if it has one, even if it's technically stale.
+     *
+     * @default false
+     */
+    checkAgeOnGet?: boolean,
+
+    /**
+     * Set new TTL, applied only when `updateAgeOnGet` is true
+     */
+    ttl?: number,
+  };
+}

packages/dev-middleware/package.json

@@ -22,6 +22,7 @@
     "dist"
   ],
   "dependencies": {
+    "@isaacs/ttlcache": "^1.4.1",
     "chrome-launcher": "^0.15.2",
     "connect": "^3.6.5",
     "debug": "^2.2.0",

packages/dev-middleware/src/inspector-proxy/Device.js

@@ -20,6 +20,7 @@ import type {
   SetBreakpointByUrlRequest,
 } from './types';
 
+import DeviceEventReporter from './DeviceEventReporter';
 import * as fs from 'fs';
 import * as path from 'path';
 import fetch from 'node-fetch';
@@ -90,7 +91,7 @@ export default class Device {
   // Root of the project used for relative to absolute source path conversion.
   _projectRoot: string;
 
-  _eventReporter: ?EventReporter;
+  _deviceEventReporter: ?DeviceEventReporter;
 
   constructor(
     id: string,
@@ -106,7 +107,9 @@ export default class Device {
     this._pages = [];
     this._deviceSocket = socket;
     this._projectRoot = projectRoot;
-    this._eventReporter = eventReporter;
+    this._deviceEventReporter = eventReporter
+      ? new DeviceEventReporter(eventReporter)
+      : null;
 
     // $FlowFixMe[incompatible-call]
     this._deviceSocket.on('message', (message: string) => {
@@ -126,6 +129,7 @@ export default class Device {
       this._handleMessageFromDevice(parsedMessage);
     });
     this._deviceSocket.on('close', () => {
+      this._deviceEventReporter?.logDisconnection('device');
       // Device disconnected - close debugger connection.
       if (this._debuggerConnection) {
         this._debuggerConnection.socket.close();
@@ -163,10 +167,7 @@ export default class Device {
   // 2. Forwards all messages from the debugger to device as wrappedEvent
   // 3. Sends disconnect event to device when debugger connection socket closes.
   handleDebuggerConnection(socket: WS, pageId: string) {
-    this._eventReporter?.logEvent({
-      type: 'connect_debugger_frontend',
-      status: 'success',
-    });
+    this._deviceEventReporter?.logConnection('debugger');
     // Disconnect current debugger if we already have debugger connected.
     if (this._debuggerConnection) {
       this._debuggerConnection.socket.close();
@@ -189,10 +190,14 @@ export default class Device {
       },
     });
 
+    // Clear any commands we were waiting on.
+    this._deviceEventReporter?.logDisconnection('debugger');
+
     // $FlowFixMe[incompatible-call]
     socket.on('message', (message: string) => {
       debug('(Debugger) -> (Proxy)    (Device): ' + message);
       const debuggerRequest = JSON.parse(message);
+      this._deviceEventReporter?.logRequest(debuggerRequest, 'debugger');
       const handled = this._interceptMessageFromDebugger(
         debuggerRequest,
         debuggerInfo,
@@ -211,6 +216,7 @@ export default class Device {
     });
     socket.on('close', () => {
       debug(`Debugger for page ${pageId} and ${this._name} disconnected.`);
+      this._deviceEventReporter?.logDisconnection('debugger');
       this._sendMessageToDevice({
         event: 'disconnect',
         payload: {
@@ -315,6 +321,9 @@ export default class Device {
       }
 
       const parsedPayload = JSON.parse(message.payload.wrappedEvent);
+      if ('id' in parsedPayload) {
+        this._deviceEventReporter?.logResponse(parsedPayload, 'device');
+      }
 
       if (this._debuggerConnection) {
         // Wrapping just to make flow happy :)
@@ -392,6 +401,7 @@ export default class Device {
     ];
 
     for (const message of toSend) {
+      this._deviceEventReporter?.logRequest(message, 'proxy');
       this._sendMessageToDevice({
         event: 'wrappedEvent',
         payload: {
@@ -484,11 +494,13 @@ export default class Device {
       //
       // This is not an issue in VSCode/Nuclide where the IDE knows to resume
       // at its convenience.
+      const resumeMessage = {method: 'Debugger.resume', id: 0};
+      this._deviceEventReporter?.logRequest(resumeMessage, 'proxy');
       this._sendMessageToDevice({
         event: 'wrappedEvent',
         payload: {
           pageId: this._mapToDevicePageId(debuggerInfo.pageId),
-          wrappedEvent: JSON.stringify({method: 'Debugger.resume', id: 0}),
+          wrappedEvent: JSON.stringify(resumeMessage),
         },
       });
 
@@ -548,15 +560,19 @@ export default class Device {
   _processDebuggerGetScriptSource(req: GetScriptSourceRequest, socket: WS) {
     const sendSuccessResponse = (scriptSource: string) => {
       const result: GetScriptSourceResponse = {scriptSource};
-      socket.send(JSON.stringify({id: req.id, result}));
+      const response = {id: req.id, result};
+      socket.send(JSON.stringify(response));
+      this._deviceEventReporter?.logResponse(response, 'proxy');
     };
     const sendErrorResponse = (error: string) => {
       // Tell the client that the request failed
       const result: ErrorResponse = {error: {message: error}};
-      socket.send(JSON.stringify({id: req.id, result}));
+      const response = {id: req.id, result};
+      socket.send(JSON.stringify(response));
 
       // Send to the console as well, so the user can see it
       this._sendErrorToDebugger(error);
+      this._deviceEventReporter?.logResponse(response, 'proxy');
     };
 
     const pathToSource = this._scriptIdToSourcePathMapping.get(

packages/dev-middleware/src/inspector-proxy/DeviceEventReporter.js

@@ -0,0 +1,147 @@
+/**
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *
+ * @flow strict-local
+ * @format
+ */
+
+import type {EventReporter} from '../types/EventReporter';
+import TTLCache from '@isaacs/ttlcache';
+
+type PendingCommand = {
+  method: string,
+  requestOrigin: 'proxy' | 'debugger',
+  requestTime: number,
+};
+
+class DeviceEventReporter {
+  _eventReporter: EventReporter;
+
+  _pendingCommands: TTLCache<number, PendingCommand> = new TTLCache({
+    ttl: 10000,
+    dispose: (
+      command: PendingCommand,
+      id: number,
+      reason: 'evict' | 'set' | 'delete' | 'stale',
+    ) => {
+      if (reason === 'delete' || reason === 'set') {
+        // TODO: Report clobbering ('set') using a dedicated error code
+        return;
+      }
+      this._logExpiredCommand(command);
+    },
+  });
+
+  constructor(eventReporter: EventReporter) {
+    this._eventReporter = eventReporter;
+  }
+
+  logRequest(
+    req: $ReadOnly<{id: number, method: string, ...}>,
+    origin: 'debugger' | 'proxy',
+  ): void {
+    this._pendingCommands.set(req.id, {
+      method: req.method,
+      requestOrigin: origin,
+      requestTime: Date.now(),
+    });
+  }
+
+  logResponse(
+    res: $ReadOnly<{
+      id: number,
+      error?: {message: string, data?: mixed},
+      ...
+    }>,
+    origin: 'device' | 'proxy',
+  ): void {
+    const pendingCommand = this._pendingCommands.get(res.id);
+    if (!pendingCommand) {
+      this._eventReporter.logEvent({
+        type: 'debugger_command',
+        protocol: 'CDP',
+        requestOrigin: null,
+        method: null,
+        status: 'coded_error',
+        errorCode: 'UNMATCHED_REQUEST_ID',
+        responseOrigin: 'proxy',
+        timeSinceStart: null,
+      });
+      return;
+    }
+    const timeSinceStart = Date.now() - pendingCommand.requestTime;
+    this._pendingCommands.delete(res.id);
+    if (res.error) {
+      let {message} = res.error;
+      if ('data' in res.error) {
+        message += ` (${String(res.error.data)})`;
+      }
+      this._eventReporter.logEvent({
+        type: 'debugger_command',
+        requestOrigin: pendingCommand.requestOrigin,
+        method: pendingCommand.method,
+        protocol: 'CDP',
+        status: 'coded_error',
+        errorCode: 'PROTOCOL_ERROR',
+        errorDetails: message,
+        responseOrigin: origin,
+        timeSinceStart,
+      });
+      return;
+    }
+    this._eventReporter.logEvent({
+      type: 'debugger_command',
+      protocol: 'CDP',
+      requestOrigin: pendingCommand.requestOrigin,
+      method: pendingCommand.method,
+      status: 'success',
+      responseOrigin: origin,
+      timeSinceStart,
+    });
+  }
+
+  logConnection(connectedEntity: 'debugger') {
+    this._eventReporter?.logEvent({
+      type: 'connect_debugger_frontend',
+      status: 'success',
+    });
+  }
+
+  logDisconnection(disconnectedEntity: 'device' | 'debugger') {
+    const errorCode =
+      disconnectedEntity === 'device'
+        ? 'DEVICE_DISCONNECTED'
+        : 'DEBUGGER_DISCONNECTED';
+    for (const pendingCommand of this._pendingCommands.values()) {
+      this._eventReporter.logEvent({
+        type: 'debugger_command',
+        protocol: 'CDP',
+        requestOrigin: pendingCommand.requestOrigin,
+        method: pendingCommand.method,
+        status: 'coded_error',
+        errorCode,
+        responseOrigin: 'proxy',
+        timeSinceStart: Date.now() - pendingCommand.requestTime,
+      });
+    }
+    this._pendingCommands.clear();
+  }
+
+  _logExpiredCommand(pendingCommand: PendingCommand): void {
+    this._eventReporter.logEvent({
+      type: 'debugger_command',
+      protocol: 'CDP',
+      requestOrigin: pendingCommand.requestOrigin,
+      method: pendingCommand.method,
+      status: 'coded_error',
+      errorCode: 'TIMED_OUT',
+      responseOrigin: 'proxy',
+      timeSinceStart: Date.now() - pendingCommand.requestTime,
+    });
+  }
+}
+
+export default DeviceEventReporter;

packages/dev-middleware/src/types/EventReporter.js

@@ -35,6 +35,24 @@ export type ReportableEvent =
   | {
       type: 'connect_debugger_frontend',
       ...SuccessResult<void> | ErrorResult<mixed>,
+    }
+  | {
+      type: 'debugger_command',
+      protocol: 'CDP',
+      // With some errors, the method might not be known
+      method: string | null,
+      requestOrigin: 'proxy' | 'debugger' | null,
+      responseOrigin: 'proxy' | 'device',
+      timeSinceStart: number | null,
+      ...
+        | SuccessResult<void>
+        | CodedErrorResult<
+            | 'TIMED_OUT'
+            | 'DEVICE_DISCONNECTED'
+            | 'DEBUGGER_DISCONNECTED'
+            | 'UNMATCHED_REQUEST_ID'
+            | 'PROTOCOL_ERROR',
+          >,
     };
 
 /**

yarn.lock

@@ -2061,6 +2061,11 @@
     wrap-ansi "^8.1.0"
     wrap-ansi-cjs "npm:wrap-ansi@^7.0.0"
 
+"@isaacs/ttlcache@^1.4.1":
+  version "1.4.1"
+  resolved "https://registry.yarnpkg.com/@isaacs/ttlcache/-/ttlcache-1.4.1.tgz#21fb23db34e9b6220c6ba023a0118a2dd3461ea2"
+  integrity sha512-RQgQ4uQ+pLbqXfOmieB91ejmLwvSgv9nLx6sT6sD83s7umBypgg+OIBOBbEUiJXrfpnp9j0mRhYYdzp9uqq3lA==
+
 "@istanbuljs/load-nyc-config@^1.0.0":
   version "1.1.0"
   resolved "https://registry.yarnpkg.com/@istanbuljs/load-nyc-config/-/load-nyc-config-1.1.0.tgz#fd3db1d59ecf7cf121e80650bb86712f9b55eced"