Repository: wix/Detox
Pull request #2726 (2021-04-13 12:55:15)

fix(logging): add missing log call for a new connection
## Description

Adds a new event:

```
detox[35774] DEBUG: [WSS_CREATE] Detox server listening on localhost:64680...
detox[35774] DEBUG: [WSS_CONNECTION, #64681] registered a new connection.
detox[35774] TRACE: [WS_OPEN] opened web socket to: ws://localhost:64680
detox[35774] TRACE: [WS_SEND] {"type":"login","params":{"sessionId":"23d777b4-af00-6d1a-e59e-150c95b51006","role":"tester"},"messageId":0}
detox[35774] TRACE: [WSS_GET_FROM, #64681] {"type":"login","params":{"sessionId":"23d777b4-af00-6d1a-e59e-150c95b51006","role":"tester"},"messageId":0}
detox[35774] TRACE: [SESSION_CREATED] created session 23d777b4-af00-6d1a-e59e-150c95b51006
detox[35774] TRACE: [WSS_SEND_TO, #tester] {"type":"loginSuccess","params":{"testerConnected":true,"appConnected":false},"messageId":0}
detox[35774] TRACE: [SESSION_JOINED] tester joined session 23d777b4-af00-6d1a-e59e-150c95b51006
detox[35774] TRACE: [WS_MESSAGE] {"type":"loginSuccess","params":{"testerConnected":true,"appConnected":false},"messageId":0}
```

Pay attention:

```
detox[35774] DEBUG: [WSS_CONNECTION, #64681] registered a new connection.
```

Should help with debugging https://github.com/wix/Detox/issues/2718



Patch:
diff --git a/detox/src/server/DetoxConnection.js b/detox/src/server/DetoxConnection.js
index e503171af..9323e01e5 100644
--- a/detox/src/server/DetoxConnection.js
+++ b/detox/src/server/DetoxConnection.js
@@ -5,10 +5,11 @@ const AnonymousConnectionHandler = require('./handlers/AnonymousConnectionHandle
 const logger = require('../utils/logger').child({ __filename });
 
 const EVENTS = {
-  GET: { event: 'GET_FROM' },
-  SEND: { event: 'SEND_TO' },
+  NEW: { event: 'WSS_CONNECTION' },
+  GET: { event: 'WSS_GET_FROM' },
+  SEND: { event: 'WSS_SEND_TO' },
   ERROR: { event: 'ERROR' },
-  SOCKET_ERROR: { event: 'SOCKET_ERROR' },
+  SOCKET_ERROR: { event: 'WSS_SOCKET_ERROR' },
 };
 
 class DetoxConnection {
@@ -28,6 +29,7 @@ class DetoxConnection {
     this._webSocket.on('message', this._onMessage);
     this._webSocket.on('error', this._onError);
     this._webSocket.on('close', this._onClose);
+    this._log.debug(EVENTS.NEW, 'registered a new connection.');
 
     const log = this._log;
     this._handler = new AnonymousConnectionHandler({
diff --git a/detox/src/server/DetoxServer.js b/detox/src/server/DetoxServer.js
index f138ae0b1..0f7d3da96 100644
--- a/detox/src/server/DetoxServer.js
+++ b/detox/src/server/DetoxServer.js
@@ -29,13 +29,13 @@ class DetoxServer {
     await this._startListening();
 
     const level = this._options.standalone ? 'info' : 'debug';
-    log[level](`Detox server listening on localhost:${this._options.port}...`);
+    log[level]({ event: 'WSS_CREATE' }, `Detox server listening on localhost:${this._options.port}...`);
   }
 
   async close() {
     try {
       await this._closeWithTimeout(10000);
-      log.debug({ event: 'SERVER_CLOSE' }, 'Detox server has been closed gracefully');
+      log.debug({ event: 'WSS_CLOSE' }, 'Detox server has been closed gracefully');
     } catch (e) {
       log.warn({ event: 'ERROR' },
         `Detox server has been closed abruptly! See the error details below:\n`


Test patch:
diff --git a/detox/src/server/DetoxServer.test.js b/detox/src/server/DetoxServer.test.js
index ecf7b2b3f..4bfa76ad2 100644
--- a/detox/src/server/DetoxServer.test.js
+++ b/detox/src/server/DetoxServer.test.js
@@ -47,8 +47,8 @@ describe('DetoxServer', () => {
         await server.open();
 
         const expectedString = expect.stringContaining(`localhost:${options.port}`);
-        expect(log.info).toHaveBeenCalledWith(expectedString);
-        expect(log.debug).not.toHaveBeenCalled();
+        expect(log.info).toHaveBeenCalledWith({ event: 'WSS_CREATE' }, expectedString);
+        expect(log.debug).not.toHaveBeenCalledWith({ event: 'WSS_CREATE' }, expectedString);
       } finally {
         await server.close();
       }
@@ -61,8 +61,8 @@ describe('DetoxServer', () => {
         await server.open();
 
         const expectedString = expect.stringContaining(`localhost:${options.port}`);
-        expect(log.debug).toHaveBeenCalledWith(expectedString);
-        expect(log.info).not.toHaveBeenCalled();
+        expect(log.debug).toHaveBeenCalledWith({ event: 'WSS_CREATE' }, expectedString);
+        expect(log.info).not.toHaveBeenCalledWith({ event: 'WSS_CREATE' }, expectedString);
       } finally {
         await server.close();
       }
@@ -74,7 +74,7 @@ describe('DetoxServer', () => {
       await server.close();
 
       const expectedString = expect.stringContaining(`has been closed gracefully`);
-      expect(log.debug).toHaveBeenCalledWith({ event: 'SERVER_CLOSE' }, expectedString);
+      expect(log.debug).toHaveBeenCalledWith({ event: 'WSS_CLOSE' }, expectedString);
     });
 
     it('should WARN log a message upon unsuccessful server closing (timeout case)', async () => {
diff --git a/detox/src/server/__tests__/__snapshots__/server-integration.test.js.snap b/detox/src/server/__tests__/__snapshots__/server-integration.test.js.snap
index 7d85423d6..5515a9921 100644
--- a/detox/src/server/__tests__/__snapshots__/server-integration.test.js.snap
+++ b/detox/src/server/__tests__/__snapshots__/server-integration.test.js.snap
@@ -1,5 +1,9 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
+exports[`Detox server integration "app" connects first, and then disconnects 1`] = `"registered a new connection."`;
+
+exports[`Detox server integration "tester" connects first, and then disconnects 1`] = `"registered a new connection."`;
+
 exports[`Detox server integration edge cases .registerSession - calling twice 1`] = `
 "DetoxInternalError: Cannot login the same WebSocket instance twice into the same session.
 Please report this issue on our GitHub tracker:
diff --git a/detox/src/server/__tests__/server-integration.test.js b/detox/src/server/__tests__/server-integration.test.js
index 0d5b81ff4..d491f9933 100644
--- a/detox/src/server/__tests__/server-integration.test.js
+++ b/detox/src/server/__tests__/server-integration.test.js
@@ -37,6 +37,7 @@ describe('Detox server integration', () => {
     const webSocket = new FakeWebSocket({ remotePort: 8081 });
     sessionManager.registerConnection(webSocket, webSocket.socket);
 
+    expect(getLoggerMsg('debug', 0, 1)).toMatchSnapshot();
     expect(sessionManager.getSession(webSocket)).toBe(null);
 
     webSocket.mockLogin({ messageId: 100500, role });
@@ -283,7 +284,7 @@ describe('Detox server integration', () => {
     test('app dispatches "ready" action before login', async () => {
       sessionManager.registerConnection(webSocket, webSocket.socket);
       webSocket.mockMessage({ type: 'ready', messageId: -1000 });
-      expect(getLoggerMsg('debug')).toMatchSnapshot();
+      expect(getLoggerMsg('debug', 1)).toMatchSnapshot();
     });
 
     test('socket error', () => {
@@ -293,7 +294,7 @@ describe('Detox server integration', () => {
       delete err.stack;
       webSocket.mockError(err);
 
-      expect(getLoggerMsg('warn', 0, 0)).toEqual({ event: 'SOCKET_ERROR' });
+      expect(getLoggerMsg('warn', 0, 0)).toEqual({ event: 'WSS_SOCKET_ERROR' });
       expect(getLoggerMsg('warn', 0, 1)).toMatchSnapshot();
     });
   });