logging- log socket connection uptime in dev middleware (#50016)

Summary:
Pull Request resolved: https://github.com/facebook/react-native/pull/50016

Changelog:
[General][Internal] logging- log socket connection uptime in dev middleware

Reviewed By: robhogan

Differential Revision: D71126344

fbshipit-source-id: 026bac9620ffb933d90db255b59fbf79bfed902b

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

@@ -48,7 +48,7 @@ export default class CDPMessagesQueueLogging {
       if (this.#loggingTimeout) {
         this.#loggingTimeout.refresh();
       } else {
-        this.#debounceStartMs = new Date().getTime();
+        this.#debounceStartMs = Date.now();
 
         this.#loggingTimeout = setTimeout(() => {
           this.#onHighMessageQueueSize(

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

@@ -158,6 +158,7 @@ export default class Device {
     this.#id = id;
     this.#name = name;
     this.#app = app;
+    const deviceConnectedTimestamp = Date.now();
 
     this.#messageFromDeviceQueueLogging = new CDPMessagesQueueLogging(
       (maxCDPMessageQueueSize: number, maxCDPMessageQueueMemory: number) => {
@@ -181,6 +182,7 @@ export default class Device {
             type: 'device_high_message_queue',
             maxCDPMessageQueueSize,
             maxCDPMessageQueueMemory,
+            connectionUptime: Date.now() - deviceConnectedTimestamp,
             ...debuggerSessionIDs,
           });
         }

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

@@ -59,9 +59,12 @@ class DeviceEventReporter {
 
   #metadata: DeviceMetadata;
 
+  #deviceConnectedTimestamp: number;
+
   constructor(eventReporter: EventReporter, metadata: DeviceMetadata) {
     this.#eventReporter = eventReporter;
     this.#metadata = metadata;
+    this.#deviceConnectedTimestamp = Date.now();
   }
 
   logRequest(
@@ -99,6 +102,7 @@ class DeviceEventReporter {
         pageId: metadata.pageId,
         frontendUserAgent: metadata.frontendUserAgent,
         prefersFuseboxFrontend: metadata.prefersFuseboxFrontend,
+        connectionUptime: this.#deviceConnectedTimestamp - Date.now(),
       });
       return;
     }
@@ -125,6 +129,7 @@ class DeviceEventReporter {
         pageId: pendingCommand.metadata.pageId,
         frontendUserAgent: pendingCommand.metadata.frontendUserAgent,
         prefersFuseboxFrontend: metadata.prefersFuseboxFrontend,
+        connectionUptime: this.#deviceConnectedTimestamp - Date.now(),
       });
       return;
     }
@@ -142,6 +147,7 @@ class DeviceEventReporter {
       pageId: pendingCommand.metadata.pageId,
       frontendUserAgent: pendingCommand.metadata.frontendUserAgent,
       prefersFuseboxFrontend: metadata.prefersFuseboxFrontend,
+      connectionUptime: this.#deviceConnectedTimestamp - Date.now(),
     });
   }
 
@@ -199,6 +205,7 @@ class DeviceEventReporter {
         pageId: pendingCommand.metadata.pageId,
         frontendUserAgent: pendingCommand.metadata.frontendUserAgent,
         prefersFuseboxFrontend: pendingCommand.metadata.prefersFuseboxFrontend,
+        connectionUptime: this.#deviceConnectedTimestamp - Date.now(),
       });
     }
     this.#pendingCommands.clear();
@@ -220,6 +227,7 @@ class DeviceEventReporter {
       deviceId: this.#metadata.deviceId,
       deviceName: this.#metadata.deviceName,
       pageId: null,
+      connectionUptime: this.#deviceConnectedTimestamp - Date.now(),
     });
   }
 
@@ -245,6 +253,7 @@ class DeviceEventReporter {
       pageId: pendingCommand.metadata.pageId,
       frontendUserAgent: pendingCommand.metadata.frontendUserAgent,
       prefersFuseboxFrontend: pendingCommand.metadata.prefersFuseboxFrontend,
+      connectionUptime: this.#deviceConnectedTimestamp - Date.now(),
     });
   }
 }

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

@@ -28,6 +28,7 @@ export type OnHighDelayArgs = {
   maxEventLoopDelayPercent: number,
   duration: number,
   debuggerSessionIDs: DebuggerSessionIDs,
+  connectionUptime: number,
 };
 
 export default class EventLoopPerfTracker {
@@ -44,7 +45,10 @@ export default class EventLoopPerfTracker {
     this.#eventLoopPerfMeasurementOngoing = false;
   }
 
-  trackPerfThrottled(debuggerSessionIDs: DebuggerSessionIDs): void {
+  trackPerfThrottled(
+    debuggerSessionIDs: DebuggerSessionIDs,
+    connectionUptime: number,
+  ): void {
     if (this.#eventLoopPerfMeasurementOngoing) {
       return;
     }
@@ -76,6 +80,7 @@ export default class EventLoopPerfTracker {
           maxEventLoopDelayPercent,
           duration: this.#perfMeasurementDuration,
           debuggerSessionIDs,
+          connectionUptime,
         });
       }
 

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

@@ -118,6 +118,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
           maxEventLoopDelayPercent,
           duration,
           debuggerSessionIDs,
+          connectionUptime,
         }) => {
           debug(
             "[perf] high event loop delay in the last %ds- event loop utilization='%d%' max event loop delay percent='%d%'",
@@ -131,6 +132,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
             eventLoopUtilization,
             maxEventLoopDelayPercent,
             duration,
+            connectionUptime,
             ...debuggerSessionIDs,
           });
         },
@@ -275,14 +277,13 @@ export default class InspectorProxy implements InspectorProxyQueries {
   /* returns true if proxy didn't receive any messages from
    * either the device or debugger for PROXY_IDLE_TIMEOUT_MS */
   #isIdle(): boolean {
-    return (
-      new Date().getTime() - this.#lastMessageTimestamp > PROXY_IDLE_TIMEOUT_MS
-    );
+    return Date.now() - this.#lastMessageTimestamp > PROXY_IDLE_TIMEOUT_MS;
   }
 
   #onMessageFromDeviceOrDebugger(
     message: string,
     debuggerSessionIDs: DebuggerSessionIDs,
+    connectionUptime: number,
   ): void {
     // TODO: instead remove this and any other messages in idle state we find
     // Not using JSON.parse for performance reasons. Worst case, we'll get
@@ -291,9 +292,12 @@ export default class InspectorProxy implements InspectorProxyQueries {
       return;
     }
 
-    this.#lastMessageTimestamp = new Date().getTime();
+    this.#lastMessageTimestamp = Date.now();
 
-    this.#eventLoopPerfTracker?.trackPerfThrottled(debuggerSessionIDs);
+    this.#eventLoopPerfTracker?.trackPerfThrottled(
+      debuggerSessionIDs,
+      connectionUptime,
+    );
   }
 
   // Adds websocket handler for device connections.
@@ -311,6 +315,8 @@ export default class InspectorProxy implements InspectorProxyQueries {
     });
     // $FlowFixMe[value-as-type]
     wss.on('connection', async (socket: WS, req) => {
+      const wssTimestamp = Date.now();
+
       const fallbackDeviceId = String(this.#deviceCounter++);
 
       const query = url.parse(req.url || '', true).query || {};
@@ -389,6 +395,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
               type: 'device_high_ping',
               duration: roundtripDuration,
               isIdle,
+              connectionUptime: Date.now() - wssTimestamp,
               ...debuggerSessionIDs,
             });
           },
@@ -414,6 +421,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
               type: 'device_timeout',
               duration: roundtripDuration,
               isIdle,
+              connectionUptime: Date.now() - wssTimestamp,
               ...debuggerSessionIDs,
             });
           },
@@ -425,6 +433,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
           this.#onMessageFromDeviceOrDebugger(
             message.toString(),
             debuggerSessionIDs,
+            Date.now() - wssTimestamp,
           ),
         );
 
@@ -442,6 +451,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
             code,
             reason,
             isIdle: this.#isIdle(),
+            connectionUptime: Date.now() - wssTimestamp,
             ...debuggerSessionIDs,
           });
 
@@ -477,6 +487,8 @@ export default class InspectorProxy implements InspectorProxyQueries {
     });
     // $FlowFixMe[value-as-type]
     wss.on('connection', async (socket: WS, req) => {
+      const wssTimestamp = Date.now();
+
       const query = url.parse(req.url || '', true).query || {};
       const deviceId = query.device;
       const pageId = query.page;
@@ -528,6 +540,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
               type: 'debugger_high_ping',
               duration: roundtripDuration,
               isIdle,
+              connectionUptime: Date.now() - wssTimestamp,
               ...debuggerSessionIDs,
             });
           },
@@ -553,6 +566,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
               type: 'debugger_timeout',
               duration: roundtripDuration,
               isIdle,
+              connectionUptime: Date.now() - wssTimestamp,
               ...debuggerSessionIDs,
             });
           },
@@ -564,6 +578,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
           this.#onMessageFromDeviceOrDebugger(
             message.toString(),
             debuggerSessionIDs,
+            Date.now() - wssTimestamp,
           ),
         );
 
@@ -586,6 +601,7 @@ export default class InspectorProxy implements InspectorProxyQueries {
             code,
             reason,
             isIdle: this.#isIdle(),
+            connectionUptime: Date.now() - wssTimestamp,
             ...debuggerSessionIDs,
           });
         });

packages/dev-middleware/src/types/EventReporter.js

@@ -33,6 +33,10 @@ export type DebuggerSessionIDs = {
   pageId: string | null,
 };
 
+export type ConnectionUptime = {
+  connectionUptime: number,
+};
+
 export type ReportableEvent =
   | {
       type: 'launch_debugger_frontend',
@@ -64,6 +68,7 @@ export type ReportableEvent =
       responseOrigin: 'proxy' | 'device',
       timeSinceStart: number | null,
       ...DebuggerSessionIDs,
+      ...ConnectionUptime,
       frontendUserAgent: string | null,
       prefersFuseboxFrontend: boolean | null,
       ...
@@ -91,18 +96,21 @@ export type ReportableEvent =
       message: string,
       error: string,
       errorStack: string,
+      ...ConnectionUptime,
       ...DebuggerSessionIDs,
     }
   | {
       type: 'debugger_high_ping' | 'device_high_ping',
       duration: number,
       isIdle: boolean,
+      ...ConnectionUptime,
       ...DebuggerSessionIDs,
     }
   | {
       type: 'debugger_timeout' | 'device_timeout',
       duration: number,
       isIdle: boolean,
+      ...ConnectionUptime,
       ...DebuggerSessionIDs,
     }
   | {
@@ -110,6 +118,7 @@ export type ReportableEvent =
       code: number,
       reason: string,
       isIdle: boolean,
+      ...ConnectionUptime,
       ...DebuggerSessionIDs,
     }
   | {
@@ -117,12 +126,14 @@ export type ReportableEvent =
       eventLoopUtilization: number,
       maxEventLoopDelayPercent: number,
       duration: number,
+      ...ConnectionUptime,
       ...DebuggerSessionIDs,
     }
   | {
       type: 'device_high_message_queue',
       maxCDPMessageQueueSize: number,
       maxCDPMessageQueueMemory: number,
+      ...ConnectionUptime,
       ...DebuggerSessionIDs,
     };