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({