From 20462ca984ae306d6ea829c381d91d4df1cb1cde Mon Sep 17 00:00:00 2001 From: Edmond Chui Date: Wed, 12 Jun 2024 09:45:34 -0700 Subject: [PATCH] fix timing of terminating an unresponsive debugger socket (#44811) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- .../src/inspector-proxy/InspectorProxy.js | 45 +++++++++++++------ 1 file changed, 32 insertions(+), 13 deletions(-) diff --git a/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js b/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js index b0b8264e3f1e72..293f47c9183235 100644 --- a/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js +++ b/packages/dev-middleware/src/inspector-proxy/InspectorProxy.js @@ -295,6 +295,7 @@ export default class InspectorProxy implements InspectorProxyQueries { // // 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(() => { @@ -303,27 +304,45 @@ export default class InspectorProxy implements InspectorProxyQueries { pingTimeout.refresh(); return; } - socket.ping(); - terminateTimeout = setTimeout(() => { - if (socket.readyState !== WS.OPEN) { + + 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; } - // 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(); + + 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(); - socket.on('pong', () => { + 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); });