From 21c85ef52d22fa000fb14d75f2ff3c418db32fda Mon Sep 17 00:00:00 2001 From: Vitali Zaidman Date: Mon, 3 Mar 2025 01:49:39 -0800 Subject: [PATCH] batch debug logging for cdp messages (#49726) Summary: Pull Request resolved: https://github.com/facebook/react-native/pull/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 --- flow-typed/npm/debug_v2.x.x.js | 10 +- .../src/inspector-proxy/CDPMessagesLogging.js | 99 +++++++++++++++++++ .../src/inspector-proxy/Device.js | 22 +++-- .../src/inspector-proxy/InspectorProxy.js | 6 +- 4 files changed, 123 insertions(+), 14 deletions(-) create mode 100644 packages/dev-middleware/src/inspector-proxy/CDPMessagesLogging.js diff --git a/flow-typed/npm/debug_v2.x.x.js b/flow-typed/npm/debug_v2.x.x.js index c104d8aaece..675c2fe6fce 100644 --- a/flow-typed/npm/debug_v2.x.x.js +++ b/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): void; + enable(match: string): void; + disable(): void; + enabled: () => boolean; +} + declare module 'debug' { declare module.exports: { - (namespace: string): (...Array) => void, + (namespace: string): DebugFN, enable(match: string): void, disable(): void, + enabled: () => boolean, }; } diff --git a/packages/dev-middleware/src/inspector-proxy/CDPMessagesLogging.js b/packages/dev-middleware/src/inspector-proxy/CDPMessagesLogging.js new file mode 100644 index 00000000000..868a9abdd08 --- /dev/null +++ b/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>(() => { + 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](); + } + } +} diff --git a/packages/dev-middleware/src/inspector-proxy/Device.js b/packages/dev-middleware/src/inspector-proxy/Device.js index 659946f082f..fc812b44f7c 100644 --- a/packages/dev-middleware/src/inspector-proxy/Device.js +++ b/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) {} diff --git a/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js b/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js index ce748026bed..69c5a7a14f6 100644 --- a/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js +++ b/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({