Merge pull request #1049 from snyk/feat/client-websocket-duration-logging

feat: client websocket duration logging [ACC-3075]

Author: shuaibmunshi

lib/hybrid-sdk/client/socket.ts

@@ -291,7 +291,7 @@ export const createWebSocket = (
   websocket.on('service', serviceHandler);
 
   websocket.on('close', () => {
-    closeHandler(localClientOps, identifyingMetadata);
+    closeHandler(websocket, localClientOps, identifyingMetadata);
   });
 
   return websocket;

lib/hybrid-sdk/client/socketHandlers/closeHandler.ts

@@ -1,16 +1,24 @@
 import { LoadedClientOpts } from '../../common/types/options';
 import { log as logger } from '../../../logs/logger';
+import { WebSocketConnection } from '../types/client';
 
 export const closeHandler = (
+  websocket: WebSocketConnection,
   clientOps: LoadedClientOpts,
   identifyingMetadata,
 ) => {
+  // default duration of -1 so that it is obvious if this misbehaves
+  let durationMs = -1;
+  if (websocket.connectionStartTime) {
+    durationMs = Date.now() - websocket.connectionStartTime;
+  }
   logger.warn(
     {
       url: clientOps.config.brokerServerUrl,
       token: clientOps.config.universalBrokerEnabled
         ? identifyingMetadata.integrationId
         : clientOps.config.brokerToken,
+      durationMs,
     },
     'Websocket connection to the broker server was closed.',
   );

lib/hybrid-sdk/client/socketHandlers/openHandler.ts

@@ -35,6 +35,7 @@ export const openHandler = (
     },
     'Successfully established a websocket connection to the broker server.',
   );
+  io.connectionStartTime = Date.now();
   logger.debug(
     {
       metadata,

lib/hybrid-sdk/client/types/client.ts

@@ -62,6 +62,7 @@ export interface WebSocketConnection
   socketVersion?: number;
   supportedIntegrationType: string;
   timeoutHandlerId?: NodeJS.Timeout;
+  connectionStartTime?: number;
 
   // Added by primus, but specific to the client
   socket: any;

test/unit/client/socketHandlers/closeHandler.test.ts

@@ -0,0 +1,58 @@
+import { closeHandler } from '../../../../lib/hybrid-sdk/client/socketHandlers/closeHandler';
+import { log as logger } from '../../../../lib/logs/logger';
+import { WebSocketConnection } from '../../../../lib/hybrid-sdk/client/types/client';
+import { LoadedClientOpts } from '../../../../lib/hybrid-sdk/common/types/options';
+
+jest.mock('../../../../lib/logs/logger');
+
+describe('closeHandler', () => {
+  let mockWebsocket: WebSocketConnection;
+  let mockClientOpts: LoadedClientOpts;
+
+  beforeEach(() => {
+    jest.clearAllMocks();
+    mockWebsocket = {
+      connectionStartTime: undefined,
+    } as unknown as WebSocketConnection;
+    mockClientOpts = {
+      config: {
+        brokerServerUrl: 'https://broker.snyk.io',
+        brokerToken: 'mock-token',
+        universalBrokerEnabled: false,
+      },
+    } as unknown as LoadedClientOpts;
+  });
+
+  it('should log warning with durationMs when connectionStartTime is present', () => {
+    const startTime = Date.now() - 5000; // 5 seconds ago
+    mockWebsocket.connectionStartTime = startTime;
+
+    // Mock Date.now to return startTime + 5000
+    const now = startTime + 5000;
+    jest.spyOn(Date, 'now').mockReturnValue(now);
+
+    closeHandler(mockWebsocket, mockClientOpts, {});
+
+    expect(logger.warn).toHaveBeenCalledWith(
+      expect.objectContaining({
+        durationMs: 5000,
+        url: 'https://broker.snyk.io',
+        token: 'mock-token',
+      }),
+      'Websocket connection to the broker server was closed.',
+    );
+  });
+
+  it('should log warning with durationMs -1 when connectionStartTime is undefined', () => {
+    closeHandler(mockWebsocket, mockClientOpts, {});
+
+    expect(logger.warn).toHaveBeenCalledWith(
+      expect.objectContaining({
+        durationMs: -1,
+        url: 'https://broker.snyk.io',
+        token: 'mock-token',
+      }),
+      'Websocket connection to the broker server was closed.',
+    );
+  });
+});