batch debug logging for cdp messages (facebook#49726)

Summary:
Pull Request resolved: facebook#49726

The `InspectorProxy` debug logging became incredibly spammy making it almost unuseful unless the output is manipulated so this commit batches all these cdp messages and only desplays how many were received in the span of 5s. If no messages are received, the throttle is not triggered.

To get the actual CDP messages logged, we still log these to `Metro:InspectorProxyCDPMessages`.

Changelog:
[General][Internal] batch debug logging for cdp messages

Reviewed By: robhogan

Differential Revision: D70324724

fbshipit-source-id: a269302f52e18af6c4be651758c042596abdbad8

Author: vzaidman

flow-typed/npm/debug_v2.x.x.js

@@ -11,10 +11,18 @@
 // https://github.com/visionmedia/debug
 // https://www.npmjs.com/package/debug
 
+interface DebugFN {
+  (...args: Array<mixed>): void;
+  enable(match: string): void;
+  disable(): void;
+  enabled: () => boolean;
+}
+
 declare module 'debug' {
   declare module.exports: {
-    (namespace: string): (...Array<mixed>) => void,
+    (namespace: string): DebugFN,
     enable(match: string): void,
     disable(): void,
+    enabled: () => boolean,
   };
 }

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

@@ -0,0 +1,99 @@
+/**
+ * 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
+ * @oncall react_native
+ */
+
+// $FlowFixMe[cannot-resolve-module] libdef missing in RN OSS
+import type {Timeout} from 'timers';
+
+// $FlowFixMe[cannot-resolve-module] libdef missing in RN OSS
+import {setTimeout} from 'timers';
+import util from 'util';
+
+const debug = require('debug')('Metro:InspectorProxy');
+const debugCDPMessages = require('debug')('Metro:InspectorProxyCDPMessages');
+
+const CDP_MESSAGES_BATCH_DEBUGGING_THROTTLE_MS = 5000;
+
+export type CDPMessageDestination =
+  | 'DebuggerToProxy'
+  | 'ProxyToDebugger'
+  | 'DeviceToProxy'
+  | 'ProxyToDevice';
+
+function getCDPLogPrefix(destination: CDPMessageDestination): string {
+  return util.format(
+    '[(Debugger) %s (Proxy) %s (Device)]',
+    destination === 'DebuggerToProxy'
+      ? '->'
+      : destination === 'ProxyToDebugger'
+        ? '<-'
+        : '  ',
+    destination === 'ProxyToDevice'
+      ? '->'
+      : destination === 'DeviceToProxy'
+        ? '<-'
+        : '  ',
+  );
+}
+
+export default class CDPMessagesLogging {
+  #cdpMessagesLoggingBatchingFn: {
+    [CDPMessageDestination]: () => void,
+  } = {
+    DebuggerToProxy: () => {},
+    ProxyToDebugger: () => {},
+    DeviceToProxy: () => {},
+    ProxyToDevice: () => {},
+  };
+
+  constructor() {
+    if (debug.enabled) {
+      this.#initializeThrottledCDPMessageLogging();
+    }
+  }
+
+  #initializeThrottledCDPMessageLogging(): void {
+    const batchingCounters: {[CDPMessageDestination]: number} = {
+      DebuggerToProxy: 0,
+      ProxyToDebugger: 0,
+      DeviceToProxy: 0,
+      ProxyToDevice: 0,
+    };
+
+    Object.keys(batchingCounters).forEach(destination => {
+      let timeout: Timeout | null = null;
+
+      this.#cdpMessagesLoggingBatchingFn[destination] = () => {
+        if (timeout == null) {
+          timeout = setTimeout<$ReadOnlyArray<CDPMessageDestination>>(() => {
+            debug(
+              '%s %s CDP messages received in the last %ss.',
+              getCDPLogPrefix(destination),
+              String(batchingCounters[destination]).padStart(5),
+              CDP_MESSAGES_BATCH_DEBUGGING_THROTTLE_MS / 1000,
+            );
+            batchingCounters[destination] = 0;
+            timeout = null;
+          }, CDP_MESSAGES_BATCH_DEBUGGING_THROTTLE_MS).unref();
+        }
+        batchingCounters[destination]++;
+      };
+    });
+  }
+
+  log(destination: CDPMessageDestination, message: string) {
+    if (debugCDPMessages.enabled) {
+      debugCDPMessages('%s message: %s', getCDPLogPrefix(destination), message);
+    }
+    if (debug.enabled) {
+      this.#cdpMessagesLoggingBatchingFn[destination]();
+    }
+  }
+}

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

@@ -27,6 +27,7 @@ import type {
   TargetCapabilityFlags,
 } from './types';
 
+import CDPMessagesLogging from './CDPMessagesLogging';
 import DeviceEventReporter from './DeviceEventReporter';
 import * as fs from 'fs';
 import invariant from 'invariant';
@@ -129,6 +130,8 @@ export default class Device {
   // A base HTTP(S) URL to the server, relative to this server.
   #serverRelativeBaseUrl: URL;
 
+  #cdpMessagesLogging: CDPMessagesLogging;
+
   constructor(deviceOptions: DeviceOptions) {
     this.#dangerouslyConstruct(deviceOptions);
   }
@@ -145,6 +148,7 @@ export default class Device {
     deviceRelativeBaseUrl,
     isProfilingBuild,
   }: DeviceOptions) {
+    this.#cdpMessagesLogging = new CDPMessagesLogging();
     this.#id = id;
     this.#name = name;
     this.#app = app;
@@ -173,14 +177,11 @@ export default class Device {
           if (parsedMessage.event === 'getPages') {
             // There's a 'getPages' message every second, so only show them if they change
             if (message !== this.#lastGetPagesMessage) {
-              debug(
-                '(Debugger)    (Proxy) <- (Device), getPages ping has changed: ' +
-                  message,
-              );
+              debug('Device getPages ping has changed: %s', message);
               this.#lastGetPagesMessage = message;
             }
           } else {
-            debug('(Debugger)    (Proxy) <- (Device): ' + message);
+            this.#cdpMessagesLogging.log('DeviceToProxy', message);
           }
           await this.#handleMessageFromDevice(parsedMessage);
         })
@@ -343,7 +344,7 @@ export default class Device {
             sendMessage: message => {
               try {
                 const payload = JSON.stringify(message);
-                debug('(Debugger) <- (Proxy)    (Device): ' + payload);
+                this.#cdpMessagesLogging.log('ProxyToDebugger', payload);
                 socket.send(payload);
               } catch {}
             },
@@ -361,7 +362,7 @@ export default class Device {
                     wrappedEvent: JSON.stringify(message),
                   },
                 });
-                debug('(Debugger) -> (Proxy)    (Device): ' + payload);
+                this.#cdpMessagesLogging.log('DebuggerToProxy', payload);
                 this.#deviceSocket.send(payload);
               } catch {}
             },
@@ -382,7 +383,7 @@ export default class Device {
 
     // $FlowFixMe[incompatible-call]
     socket.on('message', (message: string) => {
-      debug('(Debugger) -> (Proxy)    (Device): ' + message);
+      this.#cdpMessagesLogging.log('DebuggerToProxy', message);
       const debuggerRequest = JSON.parse(message);
       this.#deviceEventReporter?.logRequest(debuggerRequest, 'debugger', {
         pageId: this.#debuggerConnection?.pageId ?? null,
@@ -427,11 +428,12 @@ export default class Device {
       }
     });
 
+    const cdpMessagesLogging = this.#cdpMessagesLogging;
     // $FlowFixMe[method-unbinding]
     const sendFunc = socket.send;
     // $FlowFixMe[cannot-write]
     socket.send = function (message: string) {
-      debug('(Debugger) <- (Proxy)    (Device): ' + message);
+      cdpMessagesLogging.log('ProxyToDebugger', message);
       return sendFunc.call(socket, message);
     };
   }
@@ -609,7 +611,7 @@ export default class Device {
     try {
       const messageToSend = JSON.stringify(message);
       if (message.event !== 'getPages') {
-        debug('(Debugger)    (Proxy) -> (Device): %s', messageToSend);
+        this.#cdpMessagesLogging.log('ProxyToDevice', messageToSend);
       }
       this.#deviceSocket.send(messageToSend);
     } catch (error) {}

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

@@ -552,12 +552,12 @@ export default class InspectorProxy implements InspectorProxyQueries {
       const isIdle = this.#isIdle();
 
       debug(
-        "%s heartbeat ping-pong for app='%s' on device='%s' with idle='%s' took %dms",
-        socketName,
+        "[heartbeat ping-pong] [%s] %sms for app='%s' on device='%s' with idle='%s'",
+        socketName.padStart(7).padEnd(8),
+        String(roundtripDuration).padStart(5),
         debuggerSessionIDs.appId,
         debuggerSessionIDs.deviceName,
         isIdle ? 'true' : 'false',
-        roundtripDuration,
       );
 
       this.#eventReporter?.logEvent({