Files
react-native/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js
T
Edmond ChuiandFacebook GitHub Bot 20462ca984 fix timing of terminating an unresponsive debugger socket (#44811)
Summary:
Pull Request resolved: https://github.com/facebook/react-native/pull/44811

Changelog:
[General][Fixed] - Debugger frontend socket-termination countdown now begins after the ping message is actually sent

The debugger is currently disconnected if a ping-pong message is missed.

This causes the debugger to be unusable if it happens to be lagging, e.g. when the initialisation is competing with the flood of log spam T191394188

There are a few ways to fix this as discused with motiz88 and robhogan:

1. Ensure the websocket has a chance to respond, e.g. in via web worker
1. Lengthen the time allowed for the pong resopnse

I've done some digging to find the root cause of the UI being blocked in CDT, However, profiling shows that most of the work is not simple to break up, i.e. the number of expensive re-layout calls. Diving into that rabbit hole could mean accidentally writing React.

Because we ping every 10 seconds, we could get un/lucky where CDT happens to be busy _at that exact moment_, making this a flaky symptom to fix, even if we lengthen the allowed time-to-respond.

# V2+

So upon further investigation, CDT websocket is actually responding to the pings in due time:

{F1679132204}

(CDT doesn't show the ping/pong API as frames, so a custom tick/tock message was used to visualise the timing)

Over here in dev-middleware, we currently start a timeout to terminate the socket after sending the ping:

https://www.internalfb.com/code/fbsource/[813870db697a8701f2512d25a7fed730f0ec6ed9]/xplat/js/react-native-github/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js?lines=306-307

If CDT doesn't respond in time, websocket would be terminated.

But we saw CDT respond immediately above, even during the log spam, so the delay must be coming from somewhere else.

The intuition is that during the log-spam, the middleware takes a perf hit too when it's processing the spam from the device and forwarding it to the CDT websocket.

We can confirm this by passing a "sent" callback via `socket.ping(cb)`:

https://github.com/websockets/ws/blob/9bdb58070d64c33a9beeac7c732aac0f4e7e18b7/lib/websocket.js#L246-L254

This gives us the timing between calling `socket.ping()` and when the ping is actually sent.

Regular, stress-free operation without log-spam shows most pings are sent within the same millisecond:

 {F1679223326}

With the pong response grace period at 5 seconds, there's plenty of time for CDT to `pong` back. That's why it has been working in most cases.

However, during the log-spam, we easily see this send-sent delay over 5 seconds. In extreme cases, almost 30 seconds would have passed before middleware sent a message to CDT, which then responded under 2 seconds:

 {F1679163335}

This means while CDT is getting flooded and has observable lag in the UI, the smoking gun is actually the middleware.

Digging a little deeper, we know that incoming messages from the target goes into a Promise queue, including the console logs:

https://www.internalfb.com/code/fbsource/[d5d312082e9c]/xplat/js/react-native-github/packages/dev-middleware/src/inspector-proxy/Device.js?lines=155-157

This means during the flood of logs from the target, the Promise queue keeps getting chained rapidly for each message.

Meanhile, the `ws` lib uses the underlying NodeJS `Socket.write` method for `ping(…)` and `send(…)`:

https://github.com/websockets/ws/blob/9bdb58070d64c33a9beeac7c732aac0f4e7e18b7/lib/sender.js#L349

…which is guaranteed to fire the callback asynchronously:

https://github.com/nodejs/help/issues/1504#issuecomment-422879594

Promise queue is in the macro task queue, which gets priority before the micro task queue. So if the Promise queue is not cleared yet, the websocket queue will have a hard time getting executed in time – explaining the extreme send-sent durations during a log spam.

The fix is simple:

1. Start the terminate-socket-timer until the `ping` is actually sent
1. Treat any incoming message (along with `pong`s) as a terminate-socket-timer reset
    1. This also applies if `pong` comes in between `send` and `sent`, which can happen sometimes due to the async nature of the callback:

 {F1679288626}

# V1

~~In this diff, a more forgiving mechanism is introduced, i.e. CDT is allowed to miss a ping-pong roundtrip 3 times before the websocket connection is terminated.~~

~~This allows a bit more breathing room for CDT's initialisation during log spam while maintaining the same ping-pong interval for VS Code to keep the auto SSH tunnel alive.~~

Reviewed By: huntie

Differential Revision: D58220230

fbshipit-source-id: 7111c9878492d8755a6110a5cdf4ef622265001d
2024-06-12 09:45:34 -07:00

351 lines
12 KiB
JavaScript

/**
* 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
*/
import type {EventReporter} from '../types/EventReporter';
import type {Experiments} from '../types/Experiments';
import type {CreateCustomMessageHandlerFn} from './CustomMessageHandler';
import type {
JsonPagesListResponse,
JsonVersionResponse,
Page,
PageDescription,
} from './types';
import type {IncomingMessage, ServerResponse} from 'http';
// $FlowFixMe[cannot-resolve-module] libdef missing in RN OSS
import type {Timeout} from 'timers';
import Device from './Device';
import nullthrows from 'nullthrows';
// Import these from node:timers to get the correct Flow types.
// $FlowFixMe[cannot-resolve-module] libdef missing in RN OSS
import {clearTimeout, setTimeout} from 'timers';
import url from 'url';
import WS from 'ws';
const debug = require('debug')('Metro:InspectorProxy');
const WS_DEVICE_URL = '/inspector/device';
const WS_DEBUGGER_URL = '/inspector/debug';
const PAGES_LIST_JSON_URL = '/json';
const PAGES_LIST_JSON_URL_2 = '/json/list';
const PAGES_LIST_JSON_VERSION_URL = '/json/version';
const MAX_PONG_LATENCY_MS = 5000;
const DEBUGGER_HEARTBEAT_INTERVAL_MS = 10000;
const INTERNAL_ERROR_CODE = 1011;
export interface InspectorProxyQueries {
getPageDescriptions(): Array<PageDescription>;
}
/**
* Main Inspector Proxy class that connects JavaScript VM inside Android/iOS apps and JS debugger.
*/
export default class InspectorProxy implements InspectorProxyQueries {
// Root of the project used for relative to absolute source path conversion.
#projectRoot: string;
/** The base URL to the dev server from the developer machine. */
#serverBaseUrl: string;
// Maps device ID to Device instance.
#devices: Map<string, Device>;
// Internal counter for device IDs -- just gets incremented for each new device.
#deviceCounter: number = 0;
#eventReporter: ?EventReporter;
#experiments: Experiments;
// custom message handler factory allowing implementers to handle unsupported CDP messages.
#customMessageHandler: ?CreateCustomMessageHandlerFn;
constructor(
projectRoot: string,
serverBaseUrl: string,
eventReporter: ?EventReporter,
experiments: Experiments,
customMessageHandler: ?CreateCustomMessageHandlerFn,
) {
this.#projectRoot = projectRoot;
this.#serverBaseUrl = serverBaseUrl;
this.#devices = new Map();
this.#eventReporter = eventReporter;
this.#experiments = experiments;
this.#customMessageHandler = customMessageHandler;
}
getPageDescriptions(): Array<PageDescription> {
// Build list of pages from all devices.
let result: Array<PageDescription> = [];
Array.from(this.#devices.entries()).forEach(([deviceId, device]) => {
result = result.concat(
device
.getPagesList()
.map((page: Page) =>
this.#buildPageDescription(deviceId, device, page),
),
);
});
return result;
}
// Process HTTP request sent to server. We only respond to 2 HTTP requests:
// 1. /json/version returns Chrome debugger protocol version that we use
// 2. /json and /json/list returns list of page descriptions (list of inspectable apps).
// This list is combined from all the connected devices.
processRequest(
request: IncomingMessage,
response: ServerResponse,
next: (?Error) => mixed,
) {
const pathname = url.parse(request.url).pathname;
if (
pathname === PAGES_LIST_JSON_URL ||
pathname === PAGES_LIST_JSON_URL_2
) {
this.#sendJsonResponse(response, this.getPageDescriptions());
} else if (pathname === PAGES_LIST_JSON_VERSION_URL) {
this.#sendJsonResponse(response, {
Browser: 'Mobile JavaScript',
'Protocol-Version': '1.1',
});
} else {
next();
}
}
createWebSocketListeners(): {
[path: string]: WS.Server,
} {
return {
[WS_DEVICE_URL]: this.#createDeviceConnectionWSServer(),
[WS_DEBUGGER_URL]: this.#createDebuggerConnectionWSServer(),
};
}
// Converts page information received from device into PageDescription object
// that is sent to debugger.
#buildPageDescription(
deviceId: string,
device: Device,
page: Page,
): PageDescription {
const {host, protocol} = new URL(this.#serverBaseUrl);
const webSocketScheme = protocol === 'https:' ? 'wss' : 'ws';
const webSocketUrlWithoutProtocol = `${host}${WS_DEBUGGER_URL}?device=${deviceId}&page=${page.id}`;
const webSocketDebuggerUrl = `${webSocketScheme}://${webSocketUrlWithoutProtocol}`;
// For now, `/json/list` returns the legacy built-in `devtools://` URL, to
// preserve existing handling by Flipper. This may return a placeholder in
// future -- please use the `/open-debugger` endpoint.
const devtoolsFrontendUrl =
`devtools://devtools/bundled/js_app.html?experiments=true&v8only=true&${webSocketScheme}=` +
encodeURIComponent(webSocketUrlWithoutProtocol);
return {
id: `${deviceId}-${page.id}`,
title: page.title,
description: page.app,
type: 'node',
devtoolsFrontendUrl,
webSocketDebuggerUrl,
...(page.vm != null ? {vm: page.vm} : null),
deviceName: device.getName(),
reactNative: {
logicalDeviceId: deviceId,
capabilities: nullthrows(page.capabilities),
},
};
}
// Sends object as response to HTTP request.
// Just serializes object using JSON and sets required headers.
#sendJsonResponse(
response: ServerResponse,
object: JsonPagesListResponse | JsonVersionResponse,
) {
const data = JSON.stringify(object, null, 2);
response.writeHead(200, {
'Content-Type': 'application/json; charset=UTF-8',
'Cache-Control': 'no-cache',
'Content-Length': Buffer.byteLength(data).toString(),
Connection: 'close',
});
response.end(data);
}
// Adds websocket handler for device connections.
// Device connects to /inspector/device and passes device and app names as
// HTTP GET params.
// For each new websocket connection we parse device and app names and create
// new instance of Device class.
#createDeviceConnectionWSServer(): ws$WebSocketServer {
const wss = new WS.Server({
noServer: true,
perMessageDeflate: true,
// Don't crash on exceptionally large messages - assume the device is
// well-behaved and the debugger is prepared to handle large messages.
maxPayload: 0,
});
// $FlowFixMe[value-as-type]
wss.on('connection', async (socket: WS, req) => {
try {
const fallbackDeviceId = String(this.#deviceCounter++);
const query = url.parse(req.url || '', true).query || {};
const deviceId = query.device || fallbackDeviceId;
const deviceName = query.name || 'Unknown';
const appName = query.app || 'Unknown';
const oldDevice = this.#devices.get(deviceId);
const newDevice = new Device(
deviceId,
deviceName,
appName,
socket,
this.#projectRoot,
this.#eventReporter,
this.#customMessageHandler,
);
if (oldDevice) {
oldDevice.handleDuplicateDeviceConnection(newDevice);
}
this.#devices.set(deviceId, newDevice);
debug(
`Got new connection: name=${deviceName}, app=${appName}, device=${deviceId}`,
);
socket.on('close', () => {
this.#devices.delete(deviceId);
debug(`Device ${deviceName} disconnected.`);
});
} catch (e) {
console.error('error', e);
socket.close(INTERNAL_ERROR_CODE, e?.toString() ?? 'Unknown error');
}
});
return wss;
}
// Returns websocket handler for debugger connections.
// Debugger connects to webSocketDebuggerUrl that we return as part of page description
// in /json response.
// When debugger connects we try to parse device and page IDs from the query and pass
// websocket object to corresponding Device instance.
#createDebuggerConnectionWSServer(): ws$WebSocketServer {
const wss = new WS.Server({
noServer: true,
perMessageDeflate: false,
// Don't crash on exceptionally large messages - assume the debugger is
// well-behaved and the device is prepared to handle large messages.
maxPayload: 0,
});
// $FlowFixMe[value-as-type]
wss.on('connection', async (socket: WS, req) => {
try {
const query = url.parse(req.url || '', true).query || {};
const deviceId = query.device;
const pageId = query.page;
if (deviceId == null || pageId == null) {
throw new Error('Incorrect URL - must provide device and page IDs');
}
const device = this.#devices.get(deviceId);
if (device == null) {
throw new Error('Unknown device with ID ' + deviceId);
}
this.#startHeartbeat(socket, DEBUGGER_HEARTBEAT_INTERVAL_MS);
device.handleDebuggerConnection(socket, pageId, {
userAgent: req.headers['user-agent'] ?? query.userAgent ?? null,
});
} catch (e) {
console.error(e);
socket.close(INTERNAL_ERROR_CODE, e?.toString() ?? 'Unknown error');
this.#eventReporter?.logEvent({
type: 'connect_debugger_frontend',
status: 'error',
error: e,
});
}
});
return wss;
}
// Starts pinging the socket at the given interval. Compliant clients will
// respond with pong frame. This serves both to detect when the client
// has gone away without sending a close frame, and as a keepalive in cases
// where proxies may drop idle connections (e.g., VS Code tunnels).
//
// https://datatracker.ietf.org/doc/html/rfc6455#section-5.5.2
#startHeartbeat(socket: WS, intervalMs: number) {
let shouldSetTerminateTimeout = false;
let terminateTimeout = null;
const pingTimeout: Timeout = setTimeout(() => {
if (socket.readyState !== WS.OPEN) {
// May be connecting or closing, try again later.
pingTimeout.refresh();
return;
}
shouldSetTerminateTimeout = true;
socket.ping(() => {
if (!shouldSetTerminateTimeout) {
// Sometimes, this `sent` callback fires later than
// the actual pong reply.
//
// If any message came in between ping `sending` and `sent`,
// then the connection exists; and we don't need to do anything.
return;
}
shouldSetTerminateTimeout = false;
terminateTimeout = setTimeout(() => {
if (socket.readyState !== WS.OPEN) {
return;
}
// We don't use close() here because that initiates a closing handshake,
// which will not complete if the other end has gone away - 'close'
// would not be emitted.
//
// terminate() emits 'close' immediately, allowing us to handle it and
// inform any clients.
socket.terminate();
}, MAX_PONG_LATENCY_MS).unref();
});
}, intervalMs).unref();
const onAnyMessageFromDebugger = () => {
shouldSetTerminateTimeout = false;
terminateTimeout && clearTimeout(terminateTimeout);
pingTimeout.refresh();
};
socket.on('pong', onAnyMessageFromDebugger);
socket.on('message', onAnyMessageFromDebugger);
socket.on('close', () => {
shouldSetTerminateTimeout = false;
terminateTimeout && clearTimeout(terminateTimeout);
clearTimeout(pingTimeout);
});
}
}