From 4f7125f7444233e2203fccb87d6733d07e2e2f9b Mon Sep 17 00:00:00 2001 From: Massimo Saccani Date: Thu, 29 Aug 2024 18:39:12 +0200 Subject: [PATCH] Main fix for the crash of node-red due to unhandled exception. (#79) * fix: watchdog causing crashes in some cases * chore. bumped version to 1.1.0-beta.3 * fix: fixed the error handling of the Websocket * chore: added debug logging --- package-lock.json | 8 +- package.json | 8 +- src/SharedProtectWebSocket.ts | 136 ++++++++++++++++++++++++++-------- 3 files changed, 113 insertions(+), 39 deletions(-) diff --git a/package-lock.json b/package-lock.json index dd5fcea..cf7b7e1 100644 --- a/package-lock.json +++ b/package-lock.json @@ -15,7 +15,7 @@ "axios": "^1.3.5", "cookie": "^0.5.0", "lodash": "^4.17.21", - "ws": "^8.13.0" + "ws": "8.18.0" }, "devDependencies": { "@types/lodash": "^4.14.192", @@ -7162,9 +7162,9 @@ "dev": true }, "node_modules/ws": { - "version": "8.17.1", - "resolved": "https://registry.npmjs.org/ws/-/ws-8.17.1.tgz", - "integrity": "sha512-6XQFvXTkbfUOZOKKILFG1PDK2NDQs4azKQl26T0YS5CxqWLgXajbPZ+h4gZekJyRqFU8pvnbAbbs/3TgRPy+GQ==", + "version": "8.18.0", + "resolved": "https://registry.npmjs.org/ws/-/ws-8.18.0.tgz", + "integrity": "sha512-8VbfWfHLbbwu3+N6OKsOMpBdT4kXPDDB9cJk2bJ6mh9ucxdlnNvH1e+roYkKmN9Nxw2yjz7VzeO9oOz2zJ04Pw==", "engines": { "node": ">=10.0.0" }, diff --git a/package.json b/package.json index 7537378..95e1220 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "node-red-contrib-unifi-os", - "version": "1.1.0-beta.2", + "version": "1.1.0-beta.3", "description": "Nodes to access UniFi data using endpoints and websockets", "main": "build/nodes/unifi.js", "scripts": { @@ -56,9 +56,9 @@ "abortcontroller-polyfill": "^1.7.5", "axios": "^1.3.5", "cookie": "^0.5.0", - "ws": "^8.13.0", + "ws": "8.18.0", "lodash": "^4.17.21", - "async-mutex":"0.5.0" + "async-mutex": "0.5.0" }, "devDependencies": { "@types/lodash": "^4.14.192", @@ -95,4 +95,4 @@ "bufferutil": "^4.0.7", "utf-8-validate": "^5.0.10" } -} +} \ No newline at end of file diff --git a/src/SharedProtectWebSocket.ts b/src/SharedProtectWebSocket.ts index 356f527..6d551fa 100644 --- a/src/SharedProtectWebSocket.ts +++ b/src/SharedProtectWebSocket.ts @@ -34,7 +34,7 @@ export class SharedProtectWebSocket { private accessController: AccessControllerNodeType private wsLogger: Loggers private RECONNECT_TIMEOUT = 15000 - private HEARTBEAT_INTERVAL = 10000 + private HEARTBEAT_INTERVAL = 30000 private INITIAL_CONNECT_ERROR_THRESHOLD = 1000 private reconnectAttempts = 0 private currentStatus: SocketStatus = SocketStatus.UNKNOWN @@ -67,22 +67,38 @@ export class SharedProtectWebSocket { } shutdown(): void { + this.wsLogger?.debug( + 'shutdown()' + ) this.disconnect() this.callbacks = {} } - private disconnect(): void { + private async disconnect(): Promise { + + this.wsLogger?.debug( + 'Disconnecting websocket' + ) if (this.reconnectTimer) { clearTimeout(this.reconnectTimer) this.reconnectTimer = undefined } - this.ws?.removeAllListeners() - if (this.ws?.readyState === OPEN) { - this.ws?.close() - this.ws?.terminate() - } + + try { + this.ws?.removeAllListeners() + if (this.ws?.readyState === OPEN) { + //this.ws?.close() + //this.ws?.terminate() + } + this.ws?.terminate() // Terminate anyway + this.ws = undefined + } catch (error) { + this.wsLogger?.debug( + 'Disconnecting websocket error '+ (error as Error).stack + ) + } - this.ws = undefined + } private updateStatusForNodes = (Status: SocketStatus): Promise => { @@ -97,37 +113,71 @@ export class SharedProtectWebSocket { } private reconnectTimer: NodeJS.Timeout | undefined + private heartBeatTimer: NodeJS.Timeout | undefined private mutex = new Mutex() private async reset(): Promise { + this.wsLogger?.debug( + 'PONG received' + ) await this.mutex.runExclusive(async () => { if (this.reconnectTimer) { clearTimeout(this.reconnectTimer) this.reconnectTimer = undefined await this.updateStatusForNodes(SocketStatus.CONNECTED) - this.watchDog() + try { + this.watchDog() + } catch (error) { + this.wsLogger?.error( + 'reset watchdog error: ' + (error as Error).stack + ) + } } }) } private async watchDog(): Promise { - setTimeout(async () => { + + if (this.heartBeatTimer!==undefined) clearTimeout(this.heartBeatTimer) + this.heartBeatTimer = setTimeout(async () => { + this.wsLogger?.debug( + 'heartBeatTimer kicked in' + ) await this.updateStatusForNodes(SocketStatus.HEARTBEAT) if (!this.ws || this.ws?.readyState !== WebSocket.OPEN) { return } - this.ws?.ping() - + try { + this.wsLogger?.debug( + 'gonna PING the server...' + ) + this.ws?.ping() + } catch (error) { + this.wsLogger?.error( + 'PING error: ' + (error as Error).stack + ) + } + + if (this.reconnectTimer!==undefined) clearTimeout(this.reconnectTimer) this.reconnectTimer = setTimeout(async () => { + this.wsLogger?.debug( + 'reconnectTimer kicked in' + ) await this.mutex.runExclusive(async () => { - this.disconnect() + await this.disconnect() await this.updateStatusForNodes( SocketStatus.RECOVERING_CONNECTION ) - this.connect() + try { + await this.connect() + } catch (error) { + this.wsLogger?.error( + 'connect into reconnectTimer error: ' + (error as Error).stack + ) + } + }) }, this.RECONNECT_TIMEOUT) - - this.ws?.once('pong', this.reset.bind(this)) + }, this.HEARTBEAT_INTERVAL) } @@ -149,14 +199,13 @@ export class SharedProtectWebSocket { }) } - private processError(): void { - // This needs improving, but the watchDog is kind of taking care of stuff - } + private connectCheckInterval: NodeJS.Timeout | undefined private connectMutex = new Mutex() private async connect(): Promise { + await this.mutex.runExclusive(async () => { if (this.currentStatus !== SocketStatus.RECOVERING_CONNECTION) { await this.updateStatusForNodes(SocketStatus.CONNECTING) @@ -166,15 +215,33 @@ export class SharedProtectWebSocket { this.accessControllerConfig.wsPort || endpoints[this.accessController.controllerType].wsport const url = `${endpoints.protocol.webSocket}${this.accessControllerConfig.controllerIp}:${wsPort}/proxy/protect/ws/updates?lastUpdateId=${this.bootstrap.lastUpdateId}` - - this.ws = new WebSocket(url, { - rejectUnauthorized: false, - headers: { - Cookie: await this.accessController.getAuthCookie(), - }, - }) - - this.ws.on('error', this.processError.bind(this)) + + this.disconnect() + + try { + this.ws = new WebSocket(url, { + rejectUnauthorized: false, + headers: { + Cookie: await this.accessController.getAuthCookie(), + }, + }) + this.ws.on('error', (error) => { + this.wsLogger?.error( + 'connect(): this.ws.on(error: ' + (error as Error).stack + ) + }) + this.ws.on('pong', this.reset.bind(this)) + this.ws.on('message', this.processData.bind(this)) + } catch (error) { + this.wsLogger.error( + 'Error instantiating websocket ' + (error as Error).stack + ) + clearInterval(this.connectCheckInterval!) + this.connectCheckInterval = undefined + this.reconnectAttempts = 0 + this.watchDog() + } + this.connectCheckInterval = setInterval(async () => { await this.connectMutex.runExclusive(async () => { @@ -186,8 +253,7 @@ export class SharedProtectWebSocket { SocketStatus.CONNECTED ) this.reconnectAttempts = 0 - this.watchDog() - this.ws.on('message', this.processData.bind(this)) + this.watchDog() break case WebSocket.CONNECTING: @@ -210,7 +276,15 @@ export class SharedProtectWebSocket { this.connectCheckInterval = undefined this.reconnectAttempts++ setTimeout(async () => { - await this.connect() + try { + await this.disconnect() + await this.connect() + } catch (error) { + this.wsLogger?.error( + 'Websocket disconnecting error ' + (error as Error).stack + ) + } + }, this.RECONNECT_TIMEOUT) } break