[IMP] bus: add debug messages for websockets

Debugging websockets is cumbersome, this commit adds debug
messages to the websocket worker in order to ease debugging.

closes odoo/odoo#101099

Signed-off-by: Alexandre Kühn (aku) <aku@odoo.com>

addons/bus/static/src/services/bus_service.js

@@ -88,7 +88,10 @@ export const busService = {
         } else {
             worker.addEventListener('message', handleMessage);
         }
-        send('update_last_notification_id', multiTab.getSharedValue('last_notification_id', 0));
+        send('initialize_connection', {
+            debug: odoo.debug,
+            lastNotificationId: multiTab.getSharedValue('last_notification_id', 0),
+        });
         browser.addEventListener('unload', () => send('leave'));
 
 

addons/bus/static/src/workers/websocket_worker.js

@@ -11,7 +11,7 @@ import { debounce } from '@bus/workers/websocket_worker_utils';
 /**
  * Type of action that can be sent from the client to the worker.
  *
- * @typedef {'add_channel' | 'delete_channel' | 'force_update_channels' | 'send' | 'leave' } WorkerAction
+ * @typedef {'add_channel' | 'delete_channel' | 'force_update_channels' | 'initialize_connection', 'send' | 'leave' } WorkerAction
  */
 
 export const WEBSOCKET_CLOSE_CODES = Object.freeze({
@@ -45,6 +45,8 @@ export class WebsocketWorker {
         this.channelsByClient = new Map();
         this.connectRetryDelay = 1000;
         this.connectTimeout = null;
+        this.debugModeByClient = new Map();
+        this.isDebug = false;
         this.isReconnecting = false;
         this.lastChannelSubscription = null;
         this.lastNotificationId = 0;
@@ -121,9 +123,8 @@ export class WebsocketWorker {
                 return this._deleteChannel(client, data);
             case 'force_update_channels':
                 return this._forceUpdateChannels();
-            case 'update_last_notification_id':
-                this.lastNotificationId = data;
-                this._updateChannels();
+            case 'initialize_connection':
+                return this._initializeConnection(client, data);
         }
     }
 
@@ -179,6 +180,24 @@ export class WebsocketWorker {
      */
     _unregisterClient(client) {
         this.channelsByClient.delete(client);
+        this.debugModeByClient.delete(client);
+        this.isDebug = Object.values(this.debugModeByClient).some(debugValue => debugValue !== '');
+        this._updateChannels();
+    }
+
+    /**
+     * Initialize a client connection to this worker.
+     *
+     * @param {Object} param0
+     * @param {String} [param0.debug] Current debugging mode for the
+     * given client.
+     * @param {Number} [param0.lastNotificationId] Last notification id
+     * known by the client.
+     */
+    _initializeConnection(client, { debug, lastNotificationId }) {
+        this.lastNotificationId = lastNotificationId;
+        this.debugModeByClient[client] = debug;
+        this.isDebug = Object.values(this.debugModeByClient).some(debugValue => debugValue !== '');
         this._updateChannels();
     }
 
@@ -204,6 +223,9 @@ export class WebsocketWorker {
      * closed.
      */
     _onWebsocketClose({ code, reason }) {
+        if (this.isDebug) {
+            console.debug(`%c${new Date().toLocaleString()} - [onClose]`, 'color: #c6e; font-weight: bold;', code, reason);
+        }
         if (this.isReconnecting) {
             // Connection was not established but the close event was
             // triggered anyway. Let the onWebsocketError method handle
@@ -222,16 +244,17 @@ export class WebsocketWorker {
             // Don't wait to reconnect on keep alive timeout.
             this.connectRetryDelay = 0;
         }
-        this._onWebsocketError();
+        this._retryConnectionWithDelay();
     }
 
     /**
      * Triggered when a connection failed or failed to established.
-     * Apply an exponential back off to the reconnect attempts.
      */
     _onWebsocketError() {
-        this.connectRetryDelay = this.connectRetryDelay * 1.5 + 500 * Math.random();
-        this.connectTimeout = setTimeout(this._start.bind(this), this.connectRetryDelay);
+        if (this.isDebug) {
+            console.debug(`%c${new Date().toLocaleString()} - [onError]`, 'color: #c6e; font-weight: bold;');
+        }
+        this._retryConnectionWithDelay();
     }
 
     /**
@@ -241,6 +264,9 @@ export class WebsocketWorker {
     */
     _onWebsocketMessage(messageEv) {
         const notifications = JSON.parse(messageEv.data);
+        if (this.isDebug) {
+            console.debug(`%c${new Date().toLocaleString()} - [onMessage]`, 'color: #c6e; font-weight: bold;', notifications);
+        }
         this.lastNotificationId = notifications[notifications.length - 1].id;
         this.broadcast('notification', notifications);
     }
@@ -250,6 +276,9 @@ export class WebsocketWorker {
      * the connection to open.
      */
     _onWebsocketOpen() {
+        if (this.isDebug) {
+            console.debug(`%c${new Date().toLocaleString()} - [onOpen]`, 'color: #c6e; font-weight: bold;');
+        }
         this.messageWaitQueue.forEach(msg => this.websocket.send(msg));
         this.messageWaitQueue = [];
         this.broadcast(this.isReconnecting ? 'reconnect' : 'connect');
@@ -261,6 +290,15 @@ export class WebsocketWorker {
         this.isReconnecting = false;
     }
 
+    /**
+     * Try to reconnect to the server, an exponential back off is
+     * applied to the reconnect attempts.
+     */
+    _retryConnectionWithDelay() {
+        this.connectRetryDelay = this.connectRetryDelay * 1.5 + 500 * Math.random();
+        this.connectTimeout = setTimeout(this._start.bind(this), this.connectRetryDelay);
+    }
+
     /**
      * Send a message to the server through the websocket connection.
      * If the websocket is not open, enqueue the message and send it

addons/bus/static/tests/bus_tests.js

@@ -366,15 +366,17 @@ QUnit.module('Bus', {
         let updateLastNotificationDeferred = makeDeferred();
         patchWebsocketWorkerWithCleanup({
             _onClientMessage(_, { action, data }) {
-                assert.step(`${action} - ${data}`);
-                updateLastNotificationDeferred.resolve();
+                if (action === 'initialize_connection') {
+                    assert.step(`${action} - ${data['lastNotificationId']}`);
+                    updateLastNotificationDeferred.resolve();
+                }
             },
         });
         await makeTestEnv();
         await updateLastNotificationDeferred;
         // First bus service has never received notifications thus the
         // default is 0.
-        assert.verifySteps(['update_last_notification_id - 0']);
+        assert.verifySteps(['initialize_connection - 0']);
 
         pyEnv['bus.bus']._sendmany([
             ['lambda', 'notifType', 'beta'],
@@ -387,7 +389,7 @@ QUnit.module('Bus', {
         await makeTestEnv();
         await updateLastNotificationDeferred;
         // Second bus service sends the last known notification id.
-        assert.verifySteps([`update_last_notification_id - 1`]);
+        assert.verifySteps([`initialize_connection - 1`]);
     });
 
     QUnit.test('Last notification id reset after db change', async function (assert) {
@@ -395,15 +397,17 @@ QUnit.module('Bus', {
         let updateLastNotificationDeferred = makeDeferred();
         patchWebsocketWorkerWithCleanup({
             _onClientMessage(_, { action, data }) {
-                assert.step(`${action} - ${data}`);
-                updateLastNotificationDeferred.resolve();
+                if (action === 'initialize_connection') {
+                    assert.step(`${action} - ${data['lastNotificationId']}`);
+                    updateLastNotificationDeferred.resolve();
+                }
             },
         });
         await makeTestEnv();
         await updateLastNotificationDeferred;
         // First bus service has never received notifications thus the
         // default is 0.
-        assert.verifySteps(['update_last_notification_id - 0']);
+        assert.verifySteps(['initialize_connection - 0']);
 
         pyEnv['bus.bus']._sendmany([
             ['lambda', 'notifType', 'beta'],
@@ -417,7 +421,7 @@ QUnit.module('Bus', {
         updateLastNotificationDeferred = makeDeferred();
         await makeTestEnv();
         await updateLastNotificationDeferred;
-        assert.verifySteps([`update_last_notification_id - 0`]);
+        assert.verifySteps([`initialize_connection - 0`]);
     });
 });