From 2694c678082dd0d5177a9ef35c4f7f9bccffc1eb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Thu, 18 Feb 2021 22:24:20 +0100 Subject: [PATCH 01/22] Break out and structure creation of BLE command payloads --- plejd/PlejdBLEHandler.js | 132 +++++++++++++++++++++++++-------------- 1 file changed, 86 insertions(+), 46 deletions(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 418a072..24f20dd 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -23,6 +23,9 @@ const BLE_CMD_SCENE_TRIG = 0x0021; const BLE_CMD_TIME_UPDATE = 0x001b; const BLE_BROADCAST_DEVICE_ID = 0x01; +const BLE_REQUEST_NO_RESPONSE = 0x0110; +const BLE_REQUEST_RESPONSE = 0x0102; +// const BLE_REQUEST_READ_VALUE = 0x0103; const BLUEZ_SERVICE_NAME = 'org.bluez'; const DBUS_OM_INTERFACE = 'org.freedesktop.DBus.ObjectManager'; @@ -498,19 +501,26 @@ class PlejBLEHandler extends EventEmitter { } _setBrightness(deviceId, brightness, shouldRetry, deviceName) { - let payload = null; - let log = ''; - if (!brightness && brightness !== 0) { logger.debug( `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, ); - payload = Buffer.from(`${deviceId.toString(16).padStart(2, '0')}0110009701`, 'hex'); - log = 'ON'; + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_STATE_CHANGE, + '01', + 'TurnOn', + shouldRetry, + ); } else if (brightness <= 0) { logger.debug(`Queueing turn off ${deviceId}`); - payload = Buffer.from(`${deviceId.toString(16).padStart(2, '0')}0110009700`, 'hex'); - log = 'OFF'; + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_STATE_CHANGE, + '00', + 'TurnOff', + shouldRetry, + ); } else { if (brightness > 255) { // eslint-disable-next-line no-param-reassign @@ -520,20 +530,14 @@ class PlejBLEHandler extends EventEmitter { logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); // eslint-disable-next-line no-bitwise const brightnessVal = (brightness << 8) | brightness; - payload = Buffer.from( - `${deviceId.toString(16).padStart(2, '0')}0110009801${brightnessVal - .toString(16) - .padStart(4, '0')}`, - 'hex', + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_DIM2_CHANGE, + `01${brightnessVal.toString(16).padStart(4, '0')}`, + `Dim ${brightness}`, + shouldRetry, ); - log = `DIM ${brightness}`; } - this.writeQueue.unshift({ - deviceId, - log, - shouldRetry, - payload, - }); } async authenticate() { @@ -672,21 +676,20 @@ class PlejBLEHandler extends EventEmitter { } async _requestCurrentPlejdTime() { - logger.info('Requesting current Plejd clock time...'); + if (!this.connectedDevice) { + logger.warn('Cannot request current Plejd time, not connected.'); + return; + } + logger.info('Requesting current Plejd time...'); - // Eg: 0b0102001b: 0b: id, 0102: read, 001b: time - const payload = Buffer.from( - `${this.connectedDevice.id.toString(16).padStart(2, '0')}0102${BLE_CMD_TIME_UPDATE.toString( - 16, - ).padStart(4, '0')}`, - 'hex', + this._appendHexPayloadToWriteQueue( + this.connectedDevice.id, + BLE_CMD_TIME_UPDATE, + '', + 'RequestTime', + true, + BLE_REQUEST_RESPONSE, ); - this.writeQueue.unshift({ - deviceId: this.connectedDevice.id, - log: 'RequestTime', - shouldRetry: true, - payload, - }); setTimeout(() => this._requestCurrentPlejdTime(), 1000 * 3600); // Once per hour } @@ -936,7 +939,7 @@ class PlejBLEHandler extends EventEmitter { } else if (cmd === BLE_CMD_TIME_UPDATE) { const now = new Date(); // Guess Plejd timezone based on HA time zone - const offsetSecondsGuess = now.getTimezoneOffset() * 60; + const offsetSecondsGuess = now.getTimezoneOffset() * 60 + 250; // Todo: 4 min off // Plejd reports local unix timestamp adjust to local time zone const plejdTimestampUTC = (decoded.readInt32LE(5) + offsetSecondsGuess) * 1000; @@ -955,20 +958,16 @@ class PlejBLEHandler extends EventEmitter { `Plejd clock time off by more than 1 minute. Reported time: ${plejdTime.toString()}, diff ${diffSeconds} seconds. Time will be set hourly.`, ); if (this.connectedDevice && deviceId === this.connectedDevice.id) { - const newLocalTimestamp = (now.getTime() - offsetSecondsGuess) / 1000; + // Requested time sync by us + const newLocalTimestamp = now.getTime() / 1000 - offsetSecondsGuess; logger.info(`Setting time to ${now.toString()}`); - const payload = Buffer.alloc(10); - // E.g: 00 0110 001b 38df2360 00 - // 00: set?, 0110: don't respond, 001b: time command, 38df236000: the time - payload.write('000110001b', 0, 'hex'); - payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5); - payload.write('00', 9, 'hex'); - this.writeQueue.unshift({ - deviceId: this.connectedDevice.id, - log: 'SetTime', - shouldRetry: true, - payload, - }); + this._appendPayloadToWriteQueue( + this.connectedDevice.id, + BLE_CMD_TIME_UPDATE, + 10, + (payload) => payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5), + 'SetTime', + ); } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { logger.info('Got time response. Plejd clock time in sync with Home Assistant time'); @@ -983,6 +982,47 @@ class PlejBLEHandler extends EventEmitter { } } + _appendHexPayloadToWriteQueue( + deviceId, + command, + hexDataString, + log, + shouldRetry = true, + requestResponseCommand = BLE_REQUEST_NO_RESPONSE, + ) { + this._appendPayloadToWriteQueue( + deviceId, + command, + 5 + Math.ceil(hexDataString.length / 2), + (payload) => payload.write(hexDataString, 5, 'hex'), + log, + shouldRetry, + requestResponseCommand, + ); + } + + _appendPayloadToWriteQueue( + deviceId, + command, + bufferLength, + payloadBufferAddDataFunc, + log, + shouldRetry = true, + requestResponseCommand = BLE_REQUEST_NO_RESPONSE, + ) { + const payload = Buffer.alloc(bufferLength); + payload.writeUInt8(deviceId); + payload.writeUInt16BE(requestResponseCommand, 1); + payload.writeUInt16BE(command, 3); + payloadBufferAddDataFunc(payload); + this.writeQueue.unshift({ + deviceId, + log, + shouldRetry, + payload, + }); + } + // eslint-disable-next-line class-methods-use-this _createChallengeResponse(key, challenge) { const intermediate = crypto.createHash('sha256').update(xor(key, challenge)).digest(); From 3fdb9bad2a4a8864979f5cd0216285f462472c1c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 07:55:26 +0100 Subject: [PATCH 02/22] Split device communication and BLE handling into separate files --- plejd/Dockerfile | 12 +- plejd/PlejdAddon.js | 31 +-- plejd/PlejdBLEHandler.js | 379 ++++++++---------------------- plejd/PlejdDeviceCommunication.js | 286 ++++++++++++++++++++++ plejd/constants.js | 8 + 5 files changed, 405 insertions(+), 311 deletions(-) create mode 100644 plejd/PlejdDeviceCommunication.js create mode 100644 plejd/constants.js diff --git a/plejd/Dockerfile b/plejd/Dockerfile index 9f558a9..cb32527 100644 --- a/plejd/Dockerfile +++ b/plejd/Dockerfile @@ -7,19 +7,9 @@ ENV LANG C.UTF-8 SHELL ["/bin/bash", "-o", "pipefail", "-c"] # Copy data for add-on +COPY ./*.js /plejd/ COPY ./config.json /plejd/ -COPY ./Configuration.js /plejd/ -COPY ./DeviceRegistry.js /plejd/ -COPY ./Logger.js /plejd/ -COPY ./main.js /plejd/ -COPY ./MqttClient.js /plejd/ COPY ./package.json /plejd/ -COPY ./PlejdAddon.js /plejd/ -COPY ./PlejdApi.js /plejd/ -COPY ./PlejdBLEHandler.js /plejd/ -COPY ./Scene.js /plejd/ -COPY ./SceneManager.js /plejd/ -COPY ./SceneStep.js /plejd/ ARG BUILD_ARCH diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 9f2a18a..2fc9c72 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -3,8 +3,7 @@ const EventEmitter = require('events'); const Configuration = require('./Configuration'); const Logger = require('./Logger'); const PlejdApi = require('./PlejdApi'); -// const PlejdBLE = require('./PlejdBLE'); -const PlejdBLEHandler = require('./PlejdBLEHandler'); +const PlejdDeviceCommunication = require('./PlejdDeviceCommunication'); const MqttClient = require('./MqttClient'); const SceneManager = require('./SceneManager'); const DeviceRegistry = require('./DeviceRegistry'); @@ -16,7 +15,7 @@ class PlejdAddon extends EventEmitter { config; deviceRegistry; plejdApi; - plejdBLEHandler; + plejdDeviceCommunication; mqttClient; sceneManager; @@ -27,8 +26,8 @@ class PlejdAddon extends EventEmitter { this.deviceRegistry = new DeviceRegistry(); this.plejdApi = new PlejdApi(this.deviceRegistry); - this.plejdBLEHandler = new PlejdBLEHandler(this.deviceRegistry); - this.sceneManager = new SceneManager(this.deviceRegistry, this.plejdBLEHandler); + this.plejdDeviceCommunication = new PlejdDeviceCommunication(this.deviceRegistry); + this.sceneManager = new SceneManager(this.deviceRegistry, this.plejdDeviceCommunication); this.mqttClient = new MqttClient(this.deviceRegistry); } @@ -88,9 +87,9 @@ class PlejdAddon extends EventEmitter { } if (state === 'ON') { - this.plejdBLEHandler.turnOn(deviceId, commandObj); + this.plejdDeviceCommunication.turnOn(deviceId, commandObj); } else { - this.plejdBLEHandler.turnOff(deviceId, commandObj); + this.plejdDeviceCommunication.turnOff(deviceId, commandObj); } } catch (err) { logger.error('Error in MqttClient.stateChanged callback in main.js', err); @@ -99,15 +98,8 @@ class PlejdAddon extends EventEmitter { this.mqttClient.init(); - this.plejdBLEHandler.on('connected', () => { - logger.info('Bluetooth connected. Plejd BLE up and running!'); - }); - this.plejdBLEHandler.on('reconnecting', () => { - logger.info('Bluetooth reconnecting...'); - }); - // subscribe to changes from Plejd - this.plejdBLEHandler.on('stateChanged', (deviceId, command) => { + this.plejdDeviceCommunication.on('stateChanged', (deviceId, command) => { try { this.mqttClient.updateState(deviceId, command); } catch (err) { @@ -115,7 +107,7 @@ class PlejdAddon extends EventEmitter { } }); - this.plejdBLEHandler.on('sceneTriggered', (deviceId, sceneId) => { + this.plejdDeviceCommunication.on('sceneTriggered', (deviceId, sceneId) => { try { this.mqttClient.sceneTriggered(sceneId); } catch (err) { @@ -123,12 +115,7 @@ class PlejdAddon extends EventEmitter { } }); - try { - await this.plejdBLEHandler.init(); - } catch (err) { - logger.error('Failed init() of BLE. Starting reconnect loop.'); - await this.plejdBLEHandler.startReconnectPeriodicallyLoop(); - } + await this.plejdDeviceCommunication.init(); logger.info('Main init done'); } } diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 24f20dd..1748ca2 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -2,10 +2,12 @@ const dbus = require('dbus-next'); const crypto = require('crypto'); const xor = require('buffer-xor'); const EventEmitter = require('events'); -const Logger = require('./Logger'); const Configuration = require('./Configuration'); +const constants = require('./constants'); +const Logger = require('./Logger'); +const { COMMANDS } = constants; const logger = Logger.getLogger('plejd-ble'); // UUIDs @@ -36,9 +38,6 @@ const BLUEZ_DEVICE_ID = 'org.bluez.Device1'; const GATT_SERVICE_ID = 'org.bluez.GattService1'; const GATT_CHRC_ID = 'org.bluez.GattCharacteristic1'; -const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting -const MAX_RETRY_COUNT = 5; // Could be made a setting - const delay = (timeout) => new Promise((resolve) => setTimeout(resolve, timeout)); class PlejBLEHandler extends EventEmitter { @@ -46,24 +45,24 @@ class PlejBLEHandler extends EventEmitter { adapterProperties; config; bleDevices = []; - bleDeviceTransitionTimers = {}; bus = null; connectedDevice = null; consecutiveWriteFails; - deviceRegistry; discoveryTimeout = null; plejdService = null; - plejdDevices = {}; pingRef = null; - writeQueue = []; - writeQueueRef = null; + requestCurrentPlejdTimeRef = null; reconnectInProgress = false; // Refer to BLE-states.md regarding the internal BLE/bluez state machine of Bluetooth states // These states refer to the state machine of this file static STATES = ['MAIN_INIT', 'GET_ADAPTER_PROXY']; - static EVENTS = ['connected', 'reconnecting', 'sceneTriggered', 'stateChanged']; + static EVENTS = { + connected: 'connected', + reconnecting: 'reconnecting', + commandReceived: 'commandReceived', + }; constructor(deviceRegistry) { super(); @@ -82,8 +81,8 @@ class PlejBLEHandler extends EventEmitter { ping: null, }; - this.on('writeFailed', (error) => this.onWriteFailed(error)); - this.on('writeSuccess', () => this.onWriteSuccess()); + this.on('writeFailed', (error) => this._onWriteFailed(error)); + this.on('writeSuccess', () => this._onWriteSuccess()); } async init() { @@ -126,6 +125,33 @@ class PlejBLEHandler extends EventEmitter { logger.info('BLE init done, waiting for devices.'); } + async sendCommand(command, deviceId, data) { + let payload; + let brightnessVal; + switch (command) { + case COMMANDS.TURN_ON: + payload = this._createHexPayload(deviceId, BLE_CMD_STATE_CHANGE, '01'); + break; + case COMMANDS.TURN_OFF: + payload = this._createHexPayload(deviceId, BLE_CMD_STATE_CHANGE, '00'); + break; + case COMMANDS.DIM: + // eslint-disable-next-line no-bitwise + brightnessVal = (data << 8) | data; + payload = this._createHexPayload( + deviceId, + BLE_CMD_DIM2_CHANGE, + `01${brightnessVal.toString(16).padStart(4, '0')}`, + `Dim ${data}`, + ); + break; + default: + logger.error(`Unknown command ${command}`); + throw new Error(`Unknown command ${command}`); + } + await this._write(payload); + } + async _initDiscoveredPlejdDevice(path) { logger.debug(`initDiscoveredPlejdDevice(). Got ${path} device`); @@ -220,7 +246,6 @@ class PlejBLEHandler extends EventEmitter { } logger.info(`BLE Connected to ${this.connectedDevice.name}`); - this.emit('connected'); // Connected and authenticated, request current time and start ping if (this.config.updatePlejdClock) { @@ -228,8 +253,7 @@ class PlejBLEHandler extends EventEmitter { } else { logger.info('Plejd clock updates disabled in configuration.'); } - this.startPing(); - this.startWriteQueue(); + this._startPing(); // After we've authenticated, we need to hook up the event listener // for changes to lastData. @@ -237,8 +261,9 @@ class PlejBLEHandler extends EventEmitter { iface, properties, // invalidated (third param), - ) => this.onLastDataUpdated(iface, properties)); + ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); + this.emit(PlejBLEHandler.EVENTS.connected); } catch (err) { // This method is run on a timer, so errors can't e re-thrown. // Start reconnect loop if errors occur here @@ -342,7 +367,7 @@ class PlejBLEHandler extends EventEmitter { async _startGetPlejdDevice() { logger.verbose('Setting up interfacesAdded subscription and discovery filter'); - this.objectManager.on('InterfacesAdded', (path, interfaces) => this.onInterfacesAdded(path, interfaces)); + this.objectManager.on('InterfacesAdded', (path, interfaces) => this._onInterfacesAdded(path, interfaces)); this.adapter.SetDiscoveryFilter({ UUIDs: new dbus.Variant('as', [PLEJD_SERVICE]), @@ -375,7 +400,7 @@ class PlejBLEHandler extends EventEmitter { ); } - async onInterfacesAdded(path, interfaces) { + async _onInterfacesAdded(path, interfaces) { logger.silly(`Interface added ${path}, inspecting...`); // const [adapter, dev, service, characteristic] = path.split('/').slice(3); const interfaceKeys = Object.keys(interfaces); @@ -393,154 +418,7 @@ class PlejBLEHandler extends EventEmitter { } } - turnOn(deviceId, command) { - const deviceName = this.deviceRegistry.getDeviceName(deviceId); - logger.info( - `Plejd got turn on command for ${deviceName} (${deviceId}), brightness ${command.brightness}${ - command.transition ? `, transition: ${command.transition}` : '' - }`, - ); - this._transitionTo(deviceId, command.brightness, command.transition, deviceName); - } - - turnOff(deviceId, command) { - const deviceName = this.deviceRegistry.getDeviceName(deviceId); - logger.info( - `Plejd got turn off command for ${deviceName} (${deviceId})${ - command.transition ? `, transition: ${command.transition}` : '' - }`, - ); - this._transitionTo(deviceId, 0, command.transition, deviceName); - } - - _clearDeviceTransitionTimer(deviceId) { - if (this.bleDeviceTransitionTimers[deviceId]) { - clearInterval(this.bleDeviceTransitionTimers[deviceId]); - } - } - - _transitionTo(deviceId, targetBrightness, transition, deviceName) { - const initialBrightness = this.plejdDevices[deviceId] - ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim - : null; - this._clearDeviceTransitionTimer(deviceId); - - const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; - - if ( - transition > 1 - && isDimmable - && (initialBrightness || initialBrightness === 0) - && (targetBrightness || targetBrightness === 0) - && targetBrightness !== initialBrightness - ) { - // Transition time set, known initial and target brightness - // Calculate transition interval time based on delta brightness and max steps per second - // During transition, measure actual transition interval time and adjust stepping continously - // If transition <= 1 second, Plejd will do a better job - // than we can in transitioning so transitioning will be skipped - - const deltaBrightness = targetBrightness - initialBrightness; - const transitionSteps = Math.min( - Math.abs(deltaBrightness), - MAX_TRANSITION_STEPS_PER_SECOND * transition, - ); - const transitionInterval = (transition * 1000) / transitionSteps; - - logger.debug( - `transitioning from ${initialBrightness} to ${targetBrightness} ${ - transition ? `in ${transition} seconds` : '' - }.`, - ); - logger.verbose( - `delta brightness ${deltaBrightness}, steps ${transitionSteps}, interval ${transitionInterval} ms`, - ); - - const dtStart = new Date(); - - let nSteps = 0; - - this.bleDeviceTransitionTimers[deviceId] = setInterval(() => { - const tElapsedMs = new Date().getTime() - dtStart.getTime(); - let tElapsed = tElapsedMs / 1000; - - if (tElapsed > transition || tElapsed < 0) { - tElapsed = transition; - } - - let newBrightness = Math.round( - initialBrightness + (deltaBrightness * tElapsed) / transition, - ); - - if (tElapsed === transition) { - nSteps++; - this._clearDeviceTransitionTimer(deviceId); - newBrightness = targetBrightness; - logger.debug( - `Queueing finalize ${deviceName} (${deviceId}) transition from ${initialBrightness} to ${targetBrightness} in ${tElapsedMs}ms. Done steps ${nSteps}. Average interval ${ - tElapsedMs / (nSteps || 1) - } ms.`, - ); - this._setBrightness(deviceId, newBrightness, true, deviceName); - } else { - nSteps++; - logger.verbose( - `Queueing dim transition for ${deviceName} (${deviceId}) to ${newBrightness}. Total queue length ${this.writeQueue.length}`, - ); - this._setBrightness(deviceId, newBrightness, false, deviceName); - } - }, transitionInterval); - } else { - if (transition && isDimmable) { - logger.debug( - `Could not transition light change. Either initial value is unknown or change is too small. Requested from ${initialBrightness} to ${targetBrightness}`, - ); - } - this._setBrightness(deviceId, targetBrightness, true, deviceName); - } - } - - _setBrightness(deviceId, brightness, shouldRetry, deviceName) { - if (!brightness && brightness !== 0) { - logger.debug( - `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, - ); - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_STATE_CHANGE, - '01', - 'TurnOn', - shouldRetry, - ); - } else if (brightness <= 0) { - logger.debug(`Queueing turn off ${deviceId}`); - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_STATE_CHANGE, - '00', - 'TurnOff', - shouldRetry, - ); - } else { - if (brightness > 255) { - // eslint-disable-next-line no-param-reassign - brightness = 255; - } - - logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); - // eslint-disable-next-line no-bitwise - const brightnessVal = (brightness << 8) | brightness; - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_DIM2_CHANGE, - `01${brightnessVal.toString(16).padStart(4, '0')}`, - `Dim ${brightness}`, - shouldRetry, - ); - } - } - - async authenticate() { + async _authenticate() { logger.info('authenticate()'); try { @@ -565,6 +443,7 @@ class PlejBLEHandler extends EventEmitter { } clearInterval(this.pingRef); clearTimeout(this.writeQueueRef); + clearTimeout(this.requestCurrentPlejdTimeRef); this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ @@ -572,7 +451,7 @@ class PlejBLEHandler extends EventEmitter { while (true) { try { await delay(5000); - this.emit('reconnecting'); + this.emit(PlejBLEHandler.EVENTS.reconnecting); logger.info('Reconnecting BLE...'); await this.init(); break; @@ -585,45 +464,46 @@ class PlejBLEHandler extends EventEmitter { this.reconnectInProgress = false; } - async write(data) { - if (!data || !this.plejdService || !this.characteristics.data) { + async _write(payload) { + if (!payload || !this.plejdService || !this.characteristics.data) { logger.debug('data, plejdService or characteristics not available. Cannot write()'); - return false; + throw new Error('data, plejdService or characteristics not available. Cannot write()'); } try { - logger.verbose(`Sending ${data.length} byte(s) of data to Plejd. ${data.toString('hex')}`); - const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); + logger.verbose( + `Sending ${payload.length} byte(s) of data to Plejd. ${payload.toString('hex')}`, + ); + const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, payload); await this.characteristics.data.WriteValue([...encryptedData], {}); - await this.onWriteSuccess(); - return true; + await this._onWriteSuccess(); } catch (err) { + await this._onWriteFailed(err); if (err.message === 'In Progress') { logger.debug("Write failed due to 'In progress' ", err); - } else { - logger.debug('Write failed ', err); + throw new Error("Write failed due to 'In progress'"); } - await this.onWriteFailed(err); - return false; + logger.debug('Write failed ', err); + throw new Error(`Write failed due to ${err.message}`); } } - startPing() { + _startPing() { logger.info('startPing()'); clearInterval(this.pingRef); this.pingRef = setInterval(async () => { logger.silly('ping'); - await this.ping(); + await this._ping(); }, 3000); } // eslint-disable-next-line class-methods-use-this - onWriteSuccess() { + _onWriteSuccess() { this.consecutiveWriteFails = 0; } - async onWriteFailed(error) { + async _onWriteFailed(error) { this.consecutiveWriteFails++; logger.debug(`onWriteFailed #${this.consecutiveWriteFails} in a row.`, error); logger.verbose(`Error message: ${error.message}`); @@ -649,7 +529,7 @@ class PlejBLEHandler extends EventEmitter { } } - async ping() { + async _ping() { logger.silly('ping()'); const ping = crypto.randomBytes(1); @@ -660,19 +540,19 @@ class PlejBLEHandler extends EventEmitter { pong = await this.characteristics.ping.ReadValue({}); } catch (err) { logger.verbose(`Error pinging Plejd, calling onWriteFailed... ${err.message}`); - await this.onWriteFailed(err); + await this._onWriteFailed(err); return; } // eslint-disable-next-line no-bitwise if (((ping[0] + 1) & 0xff) !== pong[0]) { logger.verbose('Plejd ping failed, pong contains wrong data. Calling onWriteFailed...'); - await this.onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`)); + await this._onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`)); return; } logger.silly(`pong: ${pong[0]}`); - await this.onWriteSuccess(); + await this._onWriteSuccess(); } async _requestCurrentPlejdTime() { @@ -682,65 +562,23 @@ class PlejBLEHandler extends EventEmitter { } logger.info('Requesting current Plejd time...'); - this._appendHexPayloadToWriteQueue( + const payload = this._createHexPayload( this.connectedDevice.id, BLE_CMD_TIME_UPDATE, '', - 'RequestTime', - true, BLE_REQUEST_RESPONSE, ); - setTimeout(() => this._requestCurrentPlejdTime(), 1000 * 3600); // Once per hour - } - - startWriteQueue() { - logger.info('startWriteQueue()'); - clearTimeout(this.writeQueueRef); - - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); - } - - async runWriteQueue() { try { - while (this.writeQueue.length > 0) { - const queueItem = this.writeQueue.pop(); - const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); - logger.debug( - `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${queueItem.log}. Total queue length: ${this.writeQueue.length}`, - ); - - if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { - logger.verbose( - `Skipping ${deviceName} (${queueItem.deviceId}) ` - + `${queueItem.log} due to more recent command in queue.`, - ); - // Skip commands if new ones exist for the same deviceId - // still process all messages in order - } else { - // eslint-disable-next-line no-await-in-loop - const success = await this.write(queueItem.payload); - if (!success && queueItem.shouldRetry) { - queueItem.retryCount = (queueItem.retryCount || 0) + 1; - logger.debug(`Will retry command, count failed so far ${queueItem.retryCount}`); - if (queueItem.retryCount <= MAX_RETRY_COUNT) { - this.writeQueue.push(queueItem); // Add back to top of queue to be processed next; - } else { - logger.error( - `Write queue: Exceeed max retry count (${MAX_RETRY_COUNT}) for ${deviceName} (${queueItem.deviceId}). Command ${queueItem.log} failed.`, - ); - break; - } - if (queueItem.retryCount > 1) { - break; // First retry directly, consecutive after writeQueueWaitTime ms - } - } - } - } - } catch (e) { - logger.error('Error in writeQueue loop, values probably not written to Plejd', e); + this._write(payload); + } catch (error) { + logger.warn('Failed requesting time update from Plejd'); } - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + clearTimeout(this.requestCurrentPlejdTimeRef); + this.requestCurrentPlejdTimeRef = setTimeout( + () => this._requestCurrentPlejdTime(), + 1000 * 3600, + ); // Once per hour } async _processPlejdService(path, characteristics) { @@ -848,13 +686,13 @@ class PlejBLEHandler extends EventEmitter { logger.info('Connected device is a Plejd device with the right characteristics.'); this.connectedDevice = device.device; - await this.authenticate(); + await this._authenticate(); return this.connectedDevice; } // eslint-disable-next-line no-unused-vars - async onLastDataUpdated(iface, properties) { + async _onLastDataUpdated(iface, properties) { if (iface !== GATT_CHRC_ID) { return; } @@ -869,8 +707,8 @@ class PlejBLEHandler extends EventEmitter { return; } - const data = value.value; - const decoded = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); + const encryptedData = value.value; + const decoded = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, encryptedData); if (decoded.length < 5) { if (Logger.shouldLog('debug')) { @@ -904,29 +742,18 @@ class PlejBLEHandler extends EventEmitter { ); } + let command; + let data = {}; if (cmd === BLE_CMD_DIM_CHANGE || cmd === BLE_CMD_DIM2_CHANGE) { logger.debug(`${deviceName} (${deviceId}) got state+dim update. S: ${state}, D: ${dim}`); - this.emit('stateChanged', deviceId, { - state, - brightness: dim, - }); - - this.plejdDevices[deviceId] = { - state, - dim, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + command = COMMANDS.DIM; + data = { state, dim }; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_STATE_CHANGE) { logger.debug(`${deviceName} (${deviceId}) got state update. S: ${state}`); - this.emit('stateChanged', deviceId, { - state, - }); - this.plejdDevices[deviceId] = { - state, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + command = state ? COMMANDS.TURN_ON : COMMANDS.TURN_OFF; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_SCENE_TRIG) { const sceneId = state; const sceneName = this.deviceRegistry.getSceneName(sceneId); @@ -935,7 +762,9 @@ class PlejBLEHandler extends EventEmitter { `${sceneName} (${sceneId}) scene triggered (device id ${deviceId}). Name can be misleading if there is a device with the same numeric id.`, ); - this.emit('sceneTriggered', deviceId, sceneId); + command = COMMANDS.TRIGGER_SCENE; + data = { sceneId }; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_TIME_UPDATE) { const now = new Date(); // Guess Plejd timezone based on HA time zone @@ -961,13 +790,17 @@ class PlejBLEHandler extends EventEmitter { // Requested time sync by us const newLocalTimestamp = now.getTime() / 1000 - offsetSecondsGuess; logger.info(`Setting time to ${now.toString()}`); - this._appendPayloadToWriteQueue( + const payload = this._createPayload( this.connectedDevice.id, BLE_CMD_TIME_UPDATE, 10, - (payload) => payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5), - 'SetTime', + (pl) => pl.writeInt32LE(Math.trunc(newLocalTimestamp), 5), ); + try { + this.write(payload); + } catch (err) { + logger.error('Failed writing new time to Plejd. Will try again in one hour or at restart.'); + } } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { logger.info('Got time response. Plejd clock time in sync with Home Assistant time'); @@ -982,32 +815,27 @@ class PlejBLEHandler extends EventEmitter { } } - _appendHexPayloadToWriteQueue( + _createHexPayload( deviceId, command, hexDataString, - log, - shouldRetry = true, requestResponseCommand = BLE_REQUEST_NO_RESPONSE, ) { - this._appendPayloadToWriteQueue( + return this._createPayload( deviceId, command, 5 + Math.ceil(hexDataString.length / 2), (payload) => payload.write(hexDataString, 5, 'hex'), - log, - shouldRetry, requestResponseCommand, ); } - _appendPayloadToWriteQueue( + // eslint-disable-next-line class-methods-use-this + _createPayload( deviceId, command, bufferLength, payloadBufferAddDataFunc, - log, - shouldRetry = true, requestResponseCommand = BLE_REQUEST_NO_RESPONSE, ) { const payload = Buffer.alloc(bufferLength); @@ -1015,12 +843,7 @@ class PlejBLEHandler extends EventEmitter { payload.writeUInt16BE(requestResponseCommand, 1); payload.writeUInt16BE(command, 3); payloadBufferAddDataFunc(payload); - this.writeQueue.unshift({ - deviceId, - log, - shouldRetry, - payload, - }); + return payload; } // eslint-disable-next-line class-methods-use-this diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js new file mode 100644 index 0000000..86ed5f8 --- /dev/null +++ b/plejd/PlejdDeviceCommunication.js @@ -0,0 +1,286 @@ +const EventEmitter = require('events'); +const Configuration = require('./Configuration'); +const constants = require('./constants'); +const Logger = require('./Logger'); +const PlejBLEHandler = require('./PlejdBLEHandler'); + +const { COMMANDS } = constants; +const logger = Logger.getLogger('device-comm'); + +const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting +const MAX_RETRY_COUNT = 5; // Could be made a setting + +class PlejdDeviceCommunication extends EventEmitter { + bleDeviceTransitionTimers = {}; + plejdBleHandler; + config; + deviceRegistry; + plejdDevices = {}; // Todo: Move to deviceRegistry? + writeQueue = []; + writeQueueRef = null; + + static EVENTS = { + sceneTriggered: 'sceneTriggered', + stateChanged: 'stateChanged', + }; + + constructor(deviceRegistry) { + super(); + logger.info('Starting Plejd communication handler.'); + + this.plejdBleHandler = new PlejBLEHandler(deviceRegistry); + this.config = Configuration.getOptions(); + this.deviceRegistry = deviceRegistry; + + // eslint-disable-next-line max-len + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); + + this.plejdBleHandler.on('connected', () => { + logger.info('Bluetooth connected. Plejd BLE up and running!'); + this.startWriteQueue(); + }); + this.plejdBleHandler.on('reconnecting', () => { + logger.info('Bluetooth reconnecting...'); + clearTimeout(this.writeQueueRef); + }); + } + + async init() { + try { + await this.plejdBleHandler.init(); + } catch (err) { + logger.error('Failed init() of BLE. Starting reconnect loop.'); + await this.plejdBleHandler.startReconnectPeriodicallyLoop(); + } + } + + turnOn(deviceId, command) { + const deviceName = this.deviceRegistry.getDeviceName(deviceId); + logger.info( + `Plejd got turn on command for ${deviceName} (${deviceId}), brightness ${command.brightness}${ + command.transition ? `, transition: ${command.transition}` : '' + }`, + ); + this._transitionTo(deviceId, command.brightness, command.transition, deviceName); + } + + turnOff(deviceId, command) { + const deviceName = this.deviceRegistry.getDeviceName(deviceId); + logger.info( + `Plejd got turn off command for ${deviceName} (${deviceId})${ + command.transition ? `, transition: ${command.transition}` : '' + }`, + ); + this._transitionTo(deviceId, 0, command.transition, deviceName); + } + + _bleCommandReceived(deviceId, command, data) { + try { + if (command === COMMANDS.DIM) { + this.plejdDevices[deviceId] = { + state: data.state, + dim: data.dim, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: data.state, + brightness: data.dim, + }); + } else if (command === COMMANDS.TURN_ON) { + this.plejdDevices[deviceId] = { + state: data.state, + dim: 0, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: data.state, + }); + } else if (command === COMMANDS.TRIGGER_SCENE) { + this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); + } else { + logger.warn(`Unknown ble command ${command}`); + } + } catch (error) { + logger.error('Error processing ble command', error); + } + } + + _clearDeviceTransitionTimer(deviceId) { + if (this.bleDeviceTransitionTimers[deviceId]) { + clearInterval(this.bleDeviceTransitionTimers[deviceId]); + } + } + + _transitionTo(deviceId, targetBrightness, transition, deviceName) { + const initialBrightness = this.plejdDevices[deviceId] + ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim + : null; + this._clearDeviceTransitionTimer(deviceId); + + const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; + + if ( + transition > 1 + && isDimmable + && (initialBrightness || initialBrightness === 0) + && (targetBrightness || targetBrightness === 0) + && targetBrightness !== initialBrightness + ) { + // Transition time set, known initial and target brightness + // Calculate transition interval time based on delta brightness and max steps per second + // During transition, measure actual transition interval time and adjust stepping continously + // If transition <= 1 second, Plejd will do a better job + // than we can in transitioning so transitioning will be skipped + + const deltaBrightness = targetBrightness - initialBrightness; + const transitionSteps = Math.min( + Math.abs(deltaBrightness), + MAX_TRANSITION_STEPS_PER_SECOND * transition, + ); + const transitionInterval = (transition * 1000) / transitionSteps; + + logger.debug( + `transitioning from ${initialBrightness} to ${targetBrightness} ${ + transition ? `in ${transition} seconds` : '' + }.`, + ); + logger.verbose( + `delta brightness ${deltaBrightness}, steps ${transitionSteps}, interval ${transitionInterval} ms`, + ); + + const dtStart = new Date(); + + let nSteps = 0; + + this.bleDeviceTransitionTimers[deviceId] = setInterval(() => { + const tElapsedMs = new Date().getTime() - dtStart.getTime(); + let tElapsed = tElapsedMs / 1000; + + if (tElapsed > transition || tElapsed < 0) { + tElapsed = transition; + } + + let newBrightness = Math.round( + initialBrightness + (deltaBrightness * tElapsed) / transition, + ); + + if (tElapsed === transition) { + nSteps++; + this._clearDeviceTransitionTimer(deviceId); + newBrightness = targetBrightness; + logger.debug( + `Queueing finalize ${deviceName} (${deviceId}) transition from ${initialBrightness} to ${targetBrightness} in ${tElapsedMs}ms. Done steps ${nSteps}. Average interval ${ + tElapsedMs / (nSteps || 1) + } ms.`, + ); + this._setBrightness(deviceId, newBrightness, true, deviceName); + } else { + nSteps++; + logger.verbose( + `Queueing dim transition for ${deviceName} (${deviceId}) to ${newBrightness}. Total queue length ${this.writeQueue.length}`, + ); + this._setBrightness(deviceId, newBrightness, false, deviceName); + } + }, transitionInterval); + } else { + if (transition && isDimmable) { + logger.debug( + `Could not transition light change. Either initial value is unknown or change is too small. Requested from ${initialBrightness} to ${targetBrightness}`, + ); + } + this._setBrightness(deviceId, targetBrightness, true, deviceName); + } + } + + _setBrightness(deviceId, brightness, shouldRetry, deviceName) { + if (!brightness && brightness !== 0) { + logger.debug( + `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, + ); + this._appendCommandToWriteQueue(deviceId, COMMANDS.TURN_ON, null, shouldRetry); + } else if (brightness <= 0) { + logger.debug(`Queueing turn off ${deviceId}`); + this._appendCommandToWriteQueue(deviceId, COMMANDS.TURN_OFF, null, shouldRetry); + } else { + if (brightness > 255) { + // eslint-disable-next-line no-param-reassign + brightness = 255; + } + + logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); + // eslint-disable-next-line no-bitwise + this._appendCommandToWriteQueue(deviceId, COMMANDS.DIM, brightness, shouldRetry); + } + } + + _appendCommandToWriteQueue(deviceId, command, data, shouldRetry) { + this.writeQueue.unshift({ + deviceId, + command, + data, + shouldRetry, + }); + } + + startWriteQueue() { + logger.info('startWriteQueue()'); + clearTimeout(this.writeQueueRef); + + this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + } + + async runWriteQueue() { + try { + while (this.writeQueue.length > 0) { + const queueItem = this.writeQueue.pop(); + const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); + logger.debug( + `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${ + queueItem.command + }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${this.writeQueue.length}`, + ); + + if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { + logger.verbose( + `Skipping ${deviceName} (${queueItem.deviceId}) ` + + `${queueItem.command} due to more recent command in queue.`, + ); + // Skip commands if new ones exist for the same deviceId + // still process all messages in order + } else { + /* eslint-disable no-await-in-loop */ + try { + await this.plejdBleHandler.sendCommand( + queueItem.command, + queueItem.deviceId, + queueItem.data, + ); + } catch (err) { + if (queueItem.shouldRetry) { + queueItem.retryCount = (queueItem.retryCount || 0) + 1; + logger.debug(`Will retry command, count failed so far ${queueItem.retryCount}`); + if (queueItem.retryCount <= MAX_RETRY_COUNT) { + this.writeQueue.push(queueItem); // Add back to top of queue to be processed next; + } else { + logger.error( + `Write queue: Exceeed max retry count (${MAX_RETRY_COUNT}) for ${deviceName} (${queueItem.deviceId}). Command ${queueItem.command} failed.`, + ); + break; + } + if (queueItem.retryCount > 1) { + break; // First retry directly, consecutive after writeQueueWaitTime ms + } + } + } + /* eslint-enable no-await-in-loop */ + } + } + } catch (e) { + logger.error('Error in writeQueue loop, values probably not written to Plejd', e); + } + + this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + } +} + +module.exports = PlejdDeviceCommunication; diff --git a/plejd/constants.js b/plejd/constants.js new file mode 100644 index 0000000..0b69b3a --- /dev/null +++ b/plejd/constants.js @@ -0,0 +1,8 @@ +const COMMANDS = { + TURN_ON: 'Turn on', + TURN_OFF: 'Turn off', + DIM: 'Dim', + TRIGGER_SCENE: 'Trigger scene', +}; + +module.exports = { COMMANDS }; From 53e67fb487477eff98ee0d657c33d24842a10c88 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Thu, 18 Feb 2021 22:24:20 +0100 Subject: [PATCH 03/22] Break out and structure creation of BLE command payloads --- plejd/PlejdBLEHandler.js | 130 +++++++++++++++++++++++++-------------- 1 file changed, 85 insertions(+), 45 deletions(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index bef0441..24f20dd 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -23,6 +23,9 @@ const BLE_CMD_SCENE_TRIG = 0x0021; const BLE_CMD_TIME_UPDATE = 0x001b; const BLE_BROADCAST_DEVICE_ID = 0x01; +const BLE_REQUEST_NO_RESPONSE = 0x0110; +const BLE_REQUEST_RESPONSE = 0x0102; +// const BLE_REQUEST_READ_VALUE = 0x0103; const BLUEZ_SERVICE_NAME = 'org.bluez'; const DBUS_OM_INTERFACE = 'org.freedesktop.DBus.ObjectManager'; @@ -498,19 +501,26 @@ class PlejBLEHandler extends EventEmitter { } _setBrightness(deviceId, brightness, shouldRetry, deviceName) { - let payload = null; - let log = ''; - if (!brightness && brightness !== 0) { logger.debug( `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, ); - payload = Buffer.from(`${deviceId.toString(16).padStart(2, '0')}0110009701`, 'hex'); - log = 'ON'; + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_STATE_CHANGE, + '01', + 'TurnOn', + shouldRetry, + ); } else if (brightness <= 0) { logger.debug(`Queueing turn off ${deviceId}`); - payload = Buffer.from(`${deviceId.toString(16).padStart(2, '0')}0110009700`, 'hex'); - log = 'OFF'; + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_STATE_CHANGE, + '00', + 'TurnOff', + shouldRetry, + ); } else { if (brightness > 255) { // eslint-disable-next-line no-param-reassign @@ -520,20 +530,14 @@ class PlejBLEHandler extends EventEmitter { logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); // eslint-disable-next-line no-bitwise const brightnessVal = (brightness << 8) | brightness; - payload = Buffer.from( - `${deviceId.toString(16).padStart(2, '0')}0110009801${brightnessVal - .toString(16) - .padStart(4, '0')}`, - 'hex', + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_DIM2_CHANGE, + `01${brightnessVal.toString(16).padStart(4, '0')}`, + `Dim ${brightness}`, + shouldRetry, ); - log = `DIM ${brightness}`; } - this.writeQueue.unshift({ - deviceId, - log, - shouldRetry, - payload, - }); } async authenticate() { @@ -672,21 +676,20 @@ class PlejBLEHandler extends EventEmitter { } async _requestCurrentPlejdTime() { - logger.info('Requesting current Plejd clock time...'); + if (!this.connectedDevice) { + logger.warn('Cannot request current Plejd time, not connected.'); + return; + } + logger.info('Requesting current Plejd time...'); - // Eg: 0b0102001b: 0b: id, 0102: read, 001b: time - const payload = Buffer.from( - `${this.connectedDevice.id.toString(16).padStart(2, '0')}0102${BLE_CMD_TIME_UPDATE.toString( - 16, - ).padStart(4, '0')}`, - 'hex', + this._appendHexPayloadToWriteQueue( + this.connectedDevice.id, + BLE_CMD_TIME_UPDATE, + '', + 'RequestTime', + true, + BLE_REQUEST_RESPONSE, ); - this.writeQueue.unshift({ - deviceId: this.connectedDevice.id, - log: 'RequestTime', - shouldRetry: true, - payload, - }); setTimeout(() => this._requestCurrentPlejdTime(), 1000 * 3600); // Once per hour } @@ -936,7 +939,7 @@ class PlejBLEHandler extends EventEmitter { } else if (cmd === BLE_CMD_TIME_UPDATE) { const now = new Date(); // Guess Plejd timezone based on HA time zone - const offsetSecondsGuess = now.getTimezoneOffset() * 60; + const offsetSecondsGuess = now.getTimezoneOffset() * 60 + 250; // Todo: 4 min off // Plejd reports local unix timestamp adjust to local time zone const plejdTimestampUTC = (decoded.readInt32LE(5) + offsetSecondsGuess) * 1000; @@ -955,20 +958,16 @@ class PlejBLEHandler extends EventEmitter { `Plejd clock time off by more than 1 minute. Reported time: ${plejdTime.toString()}, diff ${diffSeconds} seconds. Time will be set hourly.`, ); if (this.connectedDevice && deviceId === this.connectedDevice.id) { + // Requested time sync by us const newLocalTimestamp = now.getTime() / 1000 - offsetSecondsGuess; logger.info(`Setting time to ${now.toString()}`); - const payload = Buffer.alloc(10); - // E.g: 00 0110 001b 38df2360 00 - // 00: set?, 0110: don't respond, 001b: time command, 38df236000: the time - payload.write('000110001b', 0, 'hex'); - payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5); - payload.write('00', 9, 'hex'); - this.writeQueue.unshift({ - deviceId: this.connectedDevice.id, - log: 'SetTime', - shouldRetry: true, - payload, - }); + this._appendPayloadToWriteQueue( + this.connectedDevice.id, + BLE_CMD_TIME_UPDATE, + 10, + (payload) => payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5), + 'SetTime', + ); } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { logger.info('Got time response. Plejd clock time in sync with Home Assistant time'); @@ -983,6 +982,47 @@ class PlejBLEHandler extends EventEmitter { } } + _appendHexPayloadToWriteQueue( + deviceId, + command, + hexDataString, + log, + shouldRetry = true, + requestResponseCommand = BLE_REQUEST_NO_RESPONSE, + ) { + this._appendPayloadToWriteQueue( + deviceId, + command, + 5 + Math.ceil(hexDataString.length / 2), + (payload) => payload.write(hexDataString, 5, 'hex'), + log, + shouldRetry, + requestResponseCommand, + ); + } + + _appendPayloadToWriteQueue( + deviceId, + command, + bufferLength, + payloadBufferAddDataFunc, + log, + shouldRetry = true, + requestResponseCommand = BLE_REQUEST_NO_RESPONSE, + ) { + const payload = Buffer.alloc(bufferLength); + payload.writeUInt8(deviceId); + payload.writeUInt16BE(requestResponseCommand, 1); + payload.writeUInt16BE(command, 3); + payloadBufferAddDataFunc(payload); + this.writeQueue.unshift({ + deviceId, + log, + shouldRetry, + payload, + }); + } + // eslint-disable-next-line class-methods-use-this _createChallengeResponse(key, challenge) { const intermediate = crypto.createHash('sha256').update(xor(key, challenge)).digest(); From 436ed6b75995f5c1a4949bacffd0f8e741f6a388 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 07:55:26 +0100 Subject: [PATCH 04/22] Split device communication and BLE handling into separate files --- plejd/Dockerfile | 12 +- plejd/PlejdAddon.js | 31 +-- plejd/PlejdBLEHandler.js | 379 ++++++++---------------------- plejd/PlejdDeviceCommunication.js | 286 ++++++++++++++++++++++ plejd/constants.js | 8 + 5 files changed, 405 insertions(+), 311 deletions(-) create mode 100644 plejd/PlejdDeviceCommunication.js create mode 100644 plejd/constants.js diff --git a/plejd/Dockerfile b/plejd/Dockerfile index 9f558a9..cb32527 100644 --- a/plejd/Dockerfile +++ b/plejd/Dockerfile @@ -7,19 +7,9 @@ ENV LANG C.UTF-8 SHELL ["/bin/bash", "-o", "pipefail", "-c"] # Copy data for add-on +COPY ./*.js /plejd/ COPY ./config.json /plejd/ -COPY ./Configuration.js /plejd/ -COPY ./DeviceRegistry.js /plejd/ -COPY ./Logger.js /plejd/ -COPY ./main.js /plejd/ -COPY ./MqttClient.js /plejd/ COPY ./package.json /plejd/ -COPY ./PlejdAddon.js /plejd/ -COPY ./PlejdApi.js /plejd/ -COPY ./PlejdBLEHandler.js /plejd/ -COPY ./Scene.js /plejd/ -COPY ./SceneManager.js /plejd/ -COPY ./SceneStep.js /plejd/ ARG BUILD_ARCH diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 9f2a18a..2fc9c72 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -3,8 +3,7 @@ const EventEmitter = require('events'); const Configuration = require('./Configuration'); const Logger = require('./Logger'); const PlejdApi = require('./PlejdApi'); -// const PlejdBLE = require('./PlejdBLE'); -const PlejdBLEHandler = require('./PlejdBLEHandler'); +const PlejdDeviceCommunication = require('./PlejdDeviceCommunication'); const MqttClient = require('./MqttClient'); const SceneManager = require('./SceneManager'); const DeviceRegistry = require('./DeviceRegistry'); @@ -16,7 +15,7 @@ class PlejdAddon extends EventEmitter { config; deviceRegistry; plejdApi; - plejdBLEHandler; + plejdDeviceCommunication; mqttClient; sceneManager; @@ -27,8 +26,8 @@ class PlejdAddon extends EventEmitter { this.deviceRegistry = new DeviceRegistry(); this.plejdApi = new PlejdApi(this.deviceRegistry); - this.plejdBLEHandler = new PlejdBLEHandler(this.deviceRegistry); - this.sceneManager = new SceneManager(this.deviceRegistry, this.plejdBLEHandler); + this.plejdDeviceCommunication = new PlejdDeviceCommunication(this.deviceRegistry); + this.sceneManager = new SceneManager(this.deviceRegistry, this.plejdDeviceCommunication); this.mqttClient = new MqttClient(this.deviceRegistry); } @@ -88,9 +87,9 @@ class PlejdAddon extends EventEmitter { } if (state === 'ON') { - this.plejdBLEHandler.turnOn(deviceId, commandObj); + this.plejdDeviceCommunication.turnOn(deviceId, commandObj); } else { - this.plejdBLEHandler.turnOff(deviceId, commandObj); + this.plejdDeviceCommunication.turnOff(deviceId, commandObj); } } catch (err) { logger.error('Error in MqttClient.stateChanged callback in main.js', err); @@ -99,15 +98,8 @@ class PlejdAddon extends EventEmitter { this.mqttClient.init(); - this.plejdBLEHandler.on('connected', () => { - logger.info('Bluetooth connected. Plejd BLE up and running!'); - }); - this.plejdBLEHandler.on('reconnecting', () => { - logger.info('Bluetooth reconnecting...'); - }); - // subscribe to changes from Plejd - this.plejdBLEHandler.on('stateChanged', (deviceId, command) => { + this.plejdDeviceCommunication.on('stateChanged', (deviceId, command) => { try { this.mqttClient.updateState(deviceId, command); } catch (err) { @@ -115,7 +107,7 @@ class PlejdAddon extends EventEmitter { } }); - this.plejdBLEHandler.on('sceneTriggered', (deviceId, sceneId) => { + this.plejdDeviceCommunication.on('sceneTriggered', (deviceId, sceneId) => { try { this.mqttClient.sceneTriggered(sceneId); } catch (err) { @@ -123,12 +115,7 @@ class PlejdAddon extends EventEmitter { } }); - try { - await this.plejdBLEHandler.init(); - } catch (err) { - logger.error('Failed init() of BLE. Starting reconnect loop.'); - await this.plejdBLEHandler.startReconnectPeriodicallyLoop(); - } + await this.plejdDeviceCommunication.init(); logger.info('Main init done'); } } diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 24f20dd..1748ca2 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -2,10 +2,12 @@ const dbus = require('dbus-next'); const crypto = require('crypto'); const xor = require('buffer-xor'); const EventEmitter = require('events'); -const Logger = require('./Logger'); const Configuration = require('./Configuration'); +const constants = require('./constants'); +const Logger = require('./Logger'); +const { COMMANDS } = constants; const logger = Logger.getLogger('plejd-ble'); // UUIDs @@ -36,9 +38,6 @@ const BLUEZ_DEVICE_ID = 'org.bluez.Device1'; const GATT_SERVICE_ID = 'org.bluez.GattService1'; const GATT_CHRC_ID = 'org.bluez.GattCharacteristic1'; -const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting -const MAX_RETRY_COUNT = 5; // Could be made a setting - const delay = (timeout) => new Promise((resolve) => setTimeout(resolve, timeout)); class PlejBLEHandler extends EventEmitter { @@ -46,24 +45,24 @@ class PlejBLEHandler extends EventEmitter { adapterProperties; config; bleDevices = []; - bleDeviceTransitionTimers = {}; bus = null; connectedDevice = null; consecutiveWriteFails; - deviceRegistry; discoveryTimeout = null; plejdService = null; - plejdDevices = {}; pingRef = null; - writeQueue = []; - writeQueueRef = null; + requestCurrentPlejdTimeRef = null; reconnectInProgress = false; // Refer to BLE-states.md regarding the internal BLE/bluez state machine of Bluetooth states // These states refer to the state machine of this file static STATES = ['MAIN_INIT', 'GET_ADAPTER_PROXY']; - static EVENTS = ['connected', 'reconnecting', 'sceneTriggered', 'stateChanged']; + static EVENTS = { + connected: 'connected', + reconnecting: 'reconnecting', + commandReceived: 'commandReceived', + }; constructor(deviceRegistry) { super(); @@ -82,8 +81,8 @@ class PlejBLEHandler extends EventEmitter { ping: null, }; - this.on('writeFailed', (error) => this.onWriteFailed(error)); - this.on('writeSuccess', () => this.onWriteSuccess()); + this.on('writeFailed', (error) => this._onWriteFailed(error)); + this.on('writeSuccess', () => this._onWriteSuccess()); } async init() { @@ -126,6 +125,33 @@ class PlejBLEHandler extends EventEmitter { logger.info('BLE init done, waiting for devices.'); } + async sendCommand(command, deviceId, data) { + let payload; + let brightnessVal; + switch (command) { + case COMMANDS.TURN_ON: + payload = this._createHexPayload(deviceId, BLE_CMD_STATE_CHANGE, '01'); + break; + case COMMANDS.TURN_OFF: + payload = this._createHexPayload(deviceId, BLE_CMD_STATE_CHANGE, '00'); + break; + case COMMANDS.DIM: + // eslint-disable-next-line no-bitwise + brightnessVal = (data << 8) | data; + payload = this._createHexPayload( + deviceId, + BLE_CMD_DIM2_CHANGE, + `01${brightnessVal.toString(16).padStart(4, '0')}`, + `Dim ${data}`, + ); + break; + default: + logger.error(`Unknown command ${command}`); + throw new Error(`Unknown command ${command}`); + } + await this._write(payload); + } + async _initDiscoveredPlejdDevice(path) { logger.debug(`initDiscoveredPlejdDevice(). Got ${path} device`); @@ -220,7 +246,6 @@ class PlejBLEHandler extends EventEmitter { } logger.info(`BLE Connected to ${this.connectedDevice.name}`); - this.emit('connected'); // Connected and authenticated, request current time and start ping if (this.config.updatePlejdClock) { @@ -228,8 +253,7 @@ class PlejBLEHandler extends EventEmitter { } else { logger.info('Plejd clock updates disabled in configuration.'); } - this.startPing(); - this.startWriteQueue(); + this._startPing(); // After we've authenticated, we need to hook up the event listener // for changes to lastData. @@ -237,8 +261,9 @@ class PlejBLEHandler extends EventEmitter { iface, properties, // invalidated (third param), - ) => this.onLastDataUpdated(iface, properties)); + ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); + this.emit(PlejBLEHandler.EVENTS.connected); } catch (err) { // This method is run on a timer, so errors can't e re-thrown. // Start reconnect loop if errors occur here @@ -342,7 +367,7 @@ class PlejBLEHandler extends EventEmitter { async _startGetPlejdDevice() { logger.verbose('Setting up interfacesAdded subscription and discovery filter'); - this.objectManager.on('InterfacesAdded', (path, interfaces) => this.onInterfacesAdded(path, interfaces)); + this.objectManager.on('InterfacesAdded', (path, interfaces) => this._onInterfacesAdded(path, interfaces)); this.adapter.SetDiscoveryFilter({ UUIDs: new dbus.Variant('as', [PLEJD_SERVICE]), @@ -375,7 +400,7 @@ class PlejBLEHandler extends EventEmitter { ); } - async onInterfacesAdded(path, interfaces) { + async _onInterfacesAdded(path, interfaces) { logger.silly(`Interface added ${path}, inspecting...`); // const [adapter, dev, service, characteristic] = path.split('/').slice(3); const interfaceKeys = Object.keys(interfaces); @@ -393,154 +418,7 @@ class PlejBLEHandler extends EventEmitter { } } - turnOn(deviceId, command) { - const deviceName = this.deviceRegistry.getDeviceName(deviceId); - logger.info( - `Plejd got turn on command for ${deviceName} (${deviceId}), brightness ${command.brightness}${ - command.transition ? `, transition: ${command.transition}` : '' - }`, - ); - this._transitionTo(deviceId, command.brightness, command.transition, deviceName); - } - - turnOff(deviceId, command) { - const deviceName = this.deviceRegistry.getDeviceName(deviceId); - logger.info( - `Plejd got turn off command for ${deviceName} (${deviceId})${ - command.transition ? `, transition: ${command.transition}` : '' - }`, - ); - this._transitionTo(deviceId, 0, command.transition, deviceName); - } - - _clearDeviceTransitionTimer(deviceId) { - if (this.bleDeviceTransitionTimers[deviceId]) { - clearInterval(this.bleDeviceTransitionTimers[deviceId]); - } - } - - _transitionTo(deviceId, targetBrightness, transition, deviceName) { - const initialBrightness = this.plejdDevices[deviceId] - ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim - : null; - this._clearDeviceTransitionTimer(deviceId); - - const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; - - if ( - transition > 1 - && isDimmable - && (initialBrightness || initialBrightness === 0) - && (targetBrightness || targetBrightness === 0) - && targetBrightness !== initialBrightness - ) { - // Transition time set, known initial and target brightness - // Calculate transition interval time based on delta brightness and max steps per second - // During transition, measure actual transition interval time and adjust stepping continously - // If transition <= 1 second, Plejd will do a better job - // than we can in transitioning so transitioning will be skipped - - const deltaBrightness = targetBrightness - initialBrightness; - const transitionSteps = Math.min( - Math.abs(deltaBrightness), - MAX_TRANSITION_STEPS_PER_SECOND * transition, - ); - const transitionInterval = (transition * 1000) / transitionSteps; - - logger.debug( - `transitioning from ${initialBrightness} to ${targetBrightness} ${ - transition ? `in ${transition} seconds` : '' - }.`, - ); - logger.verbose( - `delta brightness ${deltaBrightness}, steps ${transitionSteps}, interval ${transitionInterval} ms`, - ); - - const dtStart = new Date(); - - let nSteps = 0; - - this.bleDeviceTransitionTimers[deviceId] = setInterval(() => { - const tElapsedMs = new Date().getTime() - dtStart.getTime(); - let tElapsed = tElapsedMs / 1000; - - if (tElapsed > transition || tElapsed < 0) { - tElapsed = transition; - } - - let newBrightness = Math.round( - initialBrightness + (deltaBrightness * tElapsed) / transition, - ); - - if (tElapsed === transition) { - nSteps++; - this._clearDeviceTransitionTimer(deviceId); - newBrightness = targetBrightness; - logger.debug( - `Queueing finalize ${deviceName} (${deviceId}) transition from ${initialBrightness} to ${targetBrightness} in ${tElapsedMs}ms. Done steps ${nSteps}. Average interval ${ - tElapsedMs / (nSteps || 1) - } ms.`, - ); - this._setBrightness(deviceId, newBrightness, true, deviceName); - } else { - nSteps++; - logger.verbose( - `Queueing dim transition for ${deviceName} (${deviceId}) to ${newBrightness}. Total queue length ${this.writeQueue.length}`, - ); - this._setBrightness(deviceId, newBrightness, false, deviceName); - } - }, transitionInterval); - } else { - if (transition && isDimmable) { - logger.debug( - `Could not transition light change. Either initial value is unknown or change is too small. Requested from ${initialBrightness} to ${targetBrightness}`, - ); - } - this._setBrightness(deviceId, targetBrightness, true, deviceName); - } - } - - _setBrightness(deviceId, brightness, shouldRetry, deviceName) { - if (!brightness && brightness !== 0) { - logger.debug( - `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, - ); - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_STATE_CHANGE, - '01', - 'TurnOn', - shouldRetry, - ); - } else if (brightness <= 0) { - logger.debug(`Queueing turn off ${deviceId}`); - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_STATE_CHANGE, - '00', - 'TurnOff', - shouldRetry, - ); - } else { - if (brightness > 255) { - // eslint-disable-next-line no-param-reassign - brightness = 255; - } - - logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); - // eslint-disable-next-line no-bitwise - const brightnessVal = (brightness << 8) | brightness; - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_DIM2_CHANGE, - `01${brightnessVal.toString(16).padStart(4, '0')}`, - `Dim ${brightness}`, - shouldRetry, - ); - } - } - - async authenticate() { + async _authenticate() { logger.info('authenticate()'); try { @@ -565,6 +443,7 @@ class PlejBLEHandler extends EventEmitter { } clearInterval(this.pingRef); clearTimeout(this.writeQueueRef); + clearTimeout(this.requestCurrentPlejdTimeRef); this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ @@ -572,7 +451,7 @@ class PlejBLEHandler extends EventEmitter { while (true) { try { await delay(5000); - this.emit('reconnecting'); + this.emit(PlejBLEHandler.EVENTS.reconnecting); logger.info('Reconnecting BLE...'); await this.init(); break; @@ -585,45 +464,46 @@ class PlejBLEHandler extends EventEmitter { this.reconnectInProgress = false; } - async write(data) { - if (!data || !this.plejdService || !this.characteristics.data) { + async _write(payload) { + if (!payload || !this.plejdService || !this.characteristics.data) { logger.debug('data, plejdService or characteristics not available. Cannot write()'); - return false; + throw new Error('data, plejdService or characteristics not available. Cannot write()'); } try { - logger.verbose(`Sending ${data.length} byte(s) of data to Plejd. ${data.toString('hex')}`); - const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); + logger.verbose( + `Sending ${payload.length} byte(s) of data to Plejd. ${payload.toString('hex')}`, + ); + const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, payload); await this.characteristics.data.WriteValue([...encryptedData], {}); - await this.onWriteSuccess(); - return true; + await this._onWriteSuccess(); } catch (err) { + await this._onWriteFailed(err); if (err.message === 'In Progress') { logger.debug("Write failed due to 'In progress' ", err); - } else { - logger.debug('Write failed ', err); + throw new Error("Write failed due to 'In progress'"); } - await this.onWriteFailed(err); - return false; + logger.debug('Write failed ', err); + throw new Error(`Write failed due to ${err.message}`); } } - startPing() { + _startPing() { logger.info('startPing()'); clearInterval(this.pingRef); this.pingRef = setInterval(async () => { logger.silly('ping'); - await this.ping(); + await this._ping(); }, 3000); } // eslint-disable-next-line class-methods-use-this - onWriteSuccess() { + _onWriteSuccess() { this.consecutiveWriteFails = 0; } - async onWriteFailed(error) { + async _onWriteFailed(error) { this.consecutiveWriteFails++; logger.debug(`onWriteFailed #${this.consecutiveWriteFails} in a row.`, error); logger.verbose(`Error message: ${error.message}`); @@ -649,7 +529,7 @@ class PlejBLEHandler extends EventEmitter { } } - async ping() { + async _ping() { logger.silly('ping()'); const ping = crypto.randomBytes(1); @@ -660,19 +540,19 @@ class PlejBLEHandler extends EventEmitter { pong = await this.characteristics.ping.ReadValue({}); } catch (err) { logger.verbose(`Error pinging Plejd, calling onWriteFailed... ${err.message}`); - await this.onWriteFailed(err); + await this._onWriteFailed(err); return; } // eslint-disable-next-line no-bitwise if (((ping[0] + 1) & 0xff) !== pong[0]) { logger.verbose('Plejd ping failed, pong contains wrong data. Calling onWriteFailed...'); - await this.onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`)); + await this._onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`)); return; } logger.silly(`pong: ${pong[0]}`); - await this.onWriteSuccess(); + await this._onWriteSuccess(); } async _requestCurrentPlejdTime() { @@ -682,65 +562,23 @@ class PlejBLEHandler extends EventEmitter { } logger.info('Requesting current Plejd time...'); - this._appendHexPayloadToWriteQueue( + const payload = this._createHexPayload( this.connectedDevice.id, BLE_CMD_TIME_UPDATE, '', - 'RequestTime', - true, BLE_REQUEST_RESPONSE, ); - setTimeout(() => this._requestCurrentPlejdTime(), 1000 * 3600); // Once per hour - } - - startWriteQueue() { - logger.info('startWriteQueue()'); - clearTimeout(this.writeQueueRef); - - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); - } - - async runWriteQueue() { try { - while (this.writeQueue.length > 0) { - const queueItem = this.writeQueue.pop(); - const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); - logger.debug( - `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${queueItem.log}. Total queue length: ${this.writeQueue.length}`, - ); - - if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { - logger.verbose( - `Skipping ${deviceName} (${queueItem.deviceId}) ` - + `${queueItem.log} due to more recent command in queue.`, - ); - // Skip commands if new ones exist for the same deviceId - // still process all messages in order - } else { - // eslint-disable-next-line no-await-in-loop - const success = await this.write(queueItem.payload); - if (!success && queueItem.shouldRetry) { - queueItem.retryCount = (queueItem.retryCount || 0) + 1; - logger.debug(`Will retry command, count failed so far ${queueItem.retryCount}`); - if (queueItem.retryCount <= MAX_RETRY_COUNT) { - this.writeQueue.push(queueItem); // Add back to top of queue to be processed next; - } else { - logger.error( - `Write queue: Exceeed max retry count (${MAX_RETRY_COUNT}) for ${deviceName} (${queueItem.deviceId}). Command ${queueItem.log} failed.`, - ); - break; - } - if (queueItem.retryCount > 1) { - break; // First retry directly, consecutive after writeQueueWaitTime ms - } - } - } - } - } catch (e) { - logger.error('Error in writeQueue loop, values probably not written to Plejd', e); + this._write(payload); + } catch (error) { + logger.warn('Failed requesting time update from Plejd'); } - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + clearTimeout(this.requestCurrentPlejdTimeRef); + this.requestCurrentPlejdTimeRef = setTimeout( + () => this._requestCurrentPlejdTime(), + 1000 * 3600, + ); // Once per hour } async _processPlejdService(path, characteristics) { @@ -848,13 +686,13 @@ class PlejBLEHandler extends EventEmitter { logger.info('Connected device is a Plejd device with the right characteristics.'); this.connectedDevice = device.device; - await this.authenticate(); + await this._authenticate(); return this.connectedDevice; } // eslint-disable-next-line no-unused-vars - async onLastDataUpdated(iface, properties) { + async _onLastDataUpdated(iface, properties) { if (iface !== GATT_CHRC_ID) { return; } @@ -869,8 +707,8 @@ class PlejBLEHandler extends EventEmitter { return; } - const data = value.value; - const decoded = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); + const encryptedData = value.value; + const decoded = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, encryptedData); if (decoded.length < 5) { if (Logger.shouldLog('debug')) { @@ -904,29 +742,18 @@ class PlejBLEHandler extends EventEmitter { ); } + let command; + let data = {}; if (cmd === BLE_CMD_DIM_CHANGE || cmd === BLE_CMD_DIM2_CHANGE) { logger.debug(`${deviceName} (${deviceId}) got state+dim update. S: ${state}, D: ${dim}`); - this.emit('stateChanged', deviceId, { - state, - brightness: dim, - }); - - this.plejdDevices[deviceId] = { - state, - dim, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + command = COMMANDS.DIM; + data = { state, dim }; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_STATE_CHANGE) { logger.debug(`${deviceName} (${deviceId}) got state update. S: ${state}`); - this.emit('stateChanged', deviceId, { - state, - }); - this.plejdDevices[deviceId] = { - state, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + command = state ? COMMANDS.TURN_ON : COMMANDS.TURN_OFF; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_SCENE_TRIG) { const sceneId = state; const sceneName = this.deviceRegistry.getSceneName(sceneId); @@ -935,7 +762,9 @@ class PlejBLEHandler extends EventEmitter { `${sceneName} (${sceneId}) scene triggered (device id ${deviceId}). Name can be misleading if there is a device with the same numeric id.`, ); - this.emit('sceneTriggered', deviceId, sceneId); + command = COMMANDS.TRIGGER_SCENE; + data = { sceneId }; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_TIME_UPDATE) { const now = new Date(); // Guess Plejd timezone based on HA time zone @@ -961,13 +790,17 @@ class PlejBLEHandler extends EventEmitter { // Requested time sync by us const newLocalTimestamp = now.getTime() / 1000 - offsetSecondsGuess; logger.info(`Setting time to ${now.toString()}`); - this._appendPayloadToWriteQueue( + const payload = this._createPayload( this.connectedDevice.id, BLE_CMD_TIME_UPDATE, 10, - (payload) => payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5), - 'SetTime', + (pl) => pl.writeInt32LE(Math.trunc(newLocalTimestamp), 5), ); + try { + this.write(payload); + } catch (err) { + logger.error('Failed writing new time to Plejd. Will try again in one hour or at restart.'); + } } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { logger.info('Got time response. Plejd clock time in sync with Home Assistant time'); @@ -982,32 +815,27 @@ class PlejBLEHandler extends EventEmitter { } } - _appendHexPayloadToWriteQueue( + _createHexPayload( deviceId, command, hexDataString, - log, - shouldRetry = true, requestResponseCommand = BLE_REQUEST_NO_RESPONSE, ) { - this._appendPayloadToWriteQueue( + return this._createPayload( deviceId, command, 5 + Math.ceil(hexDataString.length / 2), (payload) => payload.write(hexDataString, 5, 'hex'), - log, - shouldRetry, requestResponseCommand, ); } - _appendPayloadToWriteQueue( + // eslint-disable-next-line class-methods-use-this + _createPayload( deviceId, command, bufferLength, payloadBufferAddDataFunc, - log, - shouldRetry = true, requestResponseCommand = BLE_REQUEST_NO_RESPONSE, ) { const payload = Buffer.alloc(bufferLength); @@ -1015,12 +843,7 @@ class PlejBLEHandler extends EventEmitter { payload.writeUInt16BE(requestResponseCommand, 1); payload.writeUInt16BE(command, 3); payloadBufferAddDataFunc(payload); - this.writeQueue.unshift({ - deviceId, - log, - shouldRetry, - payload, - }); + return payload; } // eslint-disable-next-line class-methods-use-this diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js new file mode 100644 index 0000000..86ed5f8 --- /dev/null +++ b/plejd/PlejdDeviceCommunication.js @@ -0,0 +1,286 @@ +const EventEmitter = require('events'); +const Configuration = require('./Configuration'); +const constants = require('./constants'); +const Logger = require('./Logger'); +const PlejBLEHandler = require('./PlejdBLEHandler'); + +const { COMMANDS } = constants; +const logger = Logger.getLogger('device-comm'); + +const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting +const MAX_RETRY_COUNT = 5; // Could be made a setting + +class PlejdDeviceCommunication extends EventEmitter { + bleDeviceTransitionTimers = {}; + plejdBleHandler; + config; + deviceRegistry; + plejdDevices = {}; // Todo: Move to deviceRegistry? + writeQueue = []; + writeQueueRef = null; + + static EVENTS = { + sceneTriggered: 'sceneTriggered', + stateChanged: 'stateChanged', + }; + + constructor(deviceRegistry) { + super(); + logger.info('Starting Plejd communication handler.'); + + this.plejdBleHandler = new PlejBLEHandler(deviceRegistry); + this.config = Configuration.getOptions(); + this.deviceRegistry = deviceRegistry; + + // eslint-disable-next-line max-len + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); + + this.plejdBleHandler.on('connected', () => { + logger.info('Bluetooth connected. Plejd BLE up and running!'); + this.startWriteQueue(); + }); + this.plejdBleHandler.on('reconnecting', () => { + logger.info('Bluetooth reconnecting...'); + clearTimeout(this.writeQueueRef); + }); + } + + async init() { + try { + await this.plejdBleHandler.init(); + } catch (err) { + logger.error('Failed init() of BLE. Starting reconnect loop.'); + await this.plejdBleHandler.startReconnectPeriodicallyLoop(); + } + } + + turnOn(deviceId, command) { + const deviceName = this.deviceRegistry.getDeviceName(deviceId); + logger.info( + `Plejd got turn on command for ${deviceName} (${deviceId}), brightness ${command.brightness}${ + command.transition ? `, transition: ${command.transition}` : '' + }`, + ); + this._transitionTo(deviceId, command.brightness, command.transition, deviceName); + } + + turnOff(deviceId, command) { + const deviceName = this.deviceRegistry.getDeviceName(deviceId); + logger.info( + `Plejd got turn off command for ${deviceName} (${deviceId})${ + command.transition ? `, transition: ${command.transition}` : '' + }`, + ); + this._transitionTo(deviceId, 0, command.transition, deviceName); + } + + _bleCommandReceived(deviceId, command, data) { + try { + if (command === COMMANDS.DIM) { + this.plejdDevices[deviceId] = { + state: data.state, + dim: data.dim, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: data.state, + brightness: data.dim, + }); + } else if (command === COMMANDS.TURN_ON) { + this.plejdDevices[deviceId] = { + state: data.state, + dim: 0, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: data.state, + }); + } else if (command === COMMANDS.TRIGGER_SCENE) { + this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); + } else { + logger.warn(`Unknown ble command ${command}`); + } + } catch (error) { + logger.error('Error processing ble command', error); + } + } + + _clearDeviceTransitionTimer(deviceId) { + if (this.bleDeviceTransitionTimers[deviceId]) { + clearInterval(this.bleDeviceTransitionTimers[deviceId]); + } + } + + _transitionTo(deviceId, targetBrightness, transition, deviceName) { + const initialBrightness = this.plejdDevices[deviceId] + ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim + : null; + this._clearDeviceTransitionTimer(deviceId); + + const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; + + if ( + transition > 1 + && isDimmable + && (initialBrightness || initialBrightness === 0) + && (targetBrightness || targetBrightness === 0) + && targetBrightness !== initialBrightness + ) { + // Transition time set, known initial and target brightness + // Calculate transition interval time based on delta brightness and max steps per second + // During transition, measure actual transition interval time and adjust stepping continously + // If transition <= 1 second, Plejd will do a better job + // than we can in transitioning so transitioning will be skipped + + const deltaBrightness = targetBrightness - initialBrightness; + const transitionSteps = Math.min( + Math.abs(deltaBrightness), + MAX_TRANSITION_STEPS_PER_SECOND * transition, + ); + const transitionInterval = (transition * 1000) / transitionSteps; + + logger.debug( + `transitioning from ${initialBrightness} to ${targetBrightness} ${ + transition ? `in ${transition} seconds` : '' + }.`, + ); + logger.verbose( + `delta brightness ${deltaBrightness}, steps ${transitionSteps}, interval ${transitionInterval} ms`, + ); + + const dtStart = new Date(); + + let nSteps = 0; + + this.bleDeviceTransitionTimers[deviceId] = setInterval(() => { + const tElapsedMs = new Date().getTime() - dtStart.getTime(); + let tElapsed = tElapsedMs / 1000; + + if (tElapsed > transition || tElapsed < 0) { + tElapsed = transition; + } + + let newBrightness = Math.round( + initialBrightness + (deltaBrightness * tElapsed) / transition, + ); + + if (tElapsed === transition) { + nSteps++; + this._clearDeviceTransitionTimer(deviceId); + newBrightness = targetBrightness; + logger.debug( + `Queueing finalize ${deviceName} (${deviceId}) transition from ${initialBrightness} to ${targetBrightness} in ${tElapsedMs}ms. Done steps ${nSteps}. Average interval ${ + tElapsedMs / (nSteps || 1) + } ms.`, + ); + this._setBrightness(deviceId, newBrightness, true, deviceName); + } else { + nSteps++; + logger.verbose( + `Queueing dim transition for ${deviceName} (${deviceId}) to ${newBrightness}. Total queue length ${this.writeQueue.length}`, + ); + this._setBrightness(deviceId, newBrightness, false, deviceName); + } + }, transitionInterval); + } else { + if (transition && isDimmable) { + logger.debug( + `Could not transition light change. Either initial value is unknown or change is too small. Requested from ${initialBrightness} to ${targetBrightness}`, + ); + } + this._setBrightness(deviceId, targetBrightness, true, deviceName); + } + } + + _setBrightness(deviceId, brightness, shouldRetry, deviceName) { + if (!brightness && brightness !== 0) { + logger.debug( + `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, + ); + this._appendCommandToWriteQueue(deviceId, COMMANDS.TURN_ON, null, shouldRetry); + } else if (brightness <= 0) { + logger.debug(`Queueing turn off ${deviceId}`); + this._appendCommandToWriteQueue(deviceId, COMMANDS.TURN_OFF, null, shouldRetry); + } else { + if (brightness > 255) { + // eslint-disable-next-line no-param-reassign + brightness = 255; + } + + logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); + // eslint-disable-next-line no-bitwise + this._appendCommandToWriteQueue(deviceId, COMMANDS.DIM, brightness, shouldRetry); + } + } + + _appendCommandToWriteQueue(deviceId, command, data, shouldRetry) { + this.writeQueue.unshift({ + deviceId, + command, + data, + shouldRetry, + }); + } + + startWriteQueue() { + logger.info('startWriteQueue()'); + clearTimeout(this.writeQueueRef); + + this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + } + + async runWriteQueue() { + try { + while (this.writeQueue.length > 0) { + const queueItem = this.writeQueue.pop(); + const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); + logger.debug( + `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${ + queueItem.command + }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${this.writeQueue.length}`, + ); + + if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { + logger.verbose( + `Skipping ${deviceName} (${queueItem.deviceId}) ` + + `${queueItem.command} due to more recent command in queue.`, + ); + // Skip commands if new ones exist for the same deviceId + // still process all messages in order + } else { + /* eslint-disable no-await-in-loop */ + try { + await this.plejdBleHandler.sendCommand( + queueItem.command, + queueItem.deviceId, + queueItem.data, + ); + } catch (err) { + if (queueItem.shouldRetry) { + queueItem.retryCount = (queueItem.retryCount || 0) + 1; + logger.debug(`Will retry command, count failed so far ${queueItem.retryCount}`); + if (queueItem.retryCount <= MAX_RETRY_COUNT) { + this.writeQueue.push(queueItem); // Add back to top of queue to be processed next; + } else { + logger.error( + `Write queue: Exceeed max retry count (${MAX_RETRY_COUNT}) for ${deviceName} (${queueItem.deviceId}). Command ${queueItem.command} failed.`, + ); + break; + } + if (queueItem.retryCount > 1) { + break; // First retry directly, consecutive after writeQueueWaitTime ms + } + } + } + /* eslint-enable no-await-in-loop */ + } + } + } catch (e) { + logger.error('Error in writeQueue loop, values probably not written to Plejd', e); + } + + this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + } +} + +module.exports = PlejdDeviceCommunication; diff --git a/plejd/constants.js b/plejd/constants.js new file mode 100644 index 0000000..0b69b3a --- /dev/null +++ b/plejd/constants.js @@ -0,0 +1,8 @@ +const COMMANDS = { + TURN_ON: 'Turn on', + TURN_OFF: 'Turn off', + DIM: 'Dim', + TRIGGER_SCENE: 'Trigger scene', +}; + +module.exports = { COMMANDS }; From e528e2be1f2dcee0de92bd84109389776e857bf1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 10:49:00 +0100 Subject: [PATCH 05/22] Fix turn off and dim commands --- plejd/MqttClient.js | 2 +- plejd/PlejdBLEHandler.js | 5 +++-- plejd/PlejdDeviceCommunication.js | 17 ++++++++++++++--- 3 files changed, 18 insertions(+), 6 deletions(-) diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index de0b09d..fa05a9d 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -133,7 +133,7 @@ class MqttClient extends EventEmitter { // Guess that id that got state command without dim value belongs to Scene, not Device // This guess could very well be wrong depending on the installation... logger.warn( - `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON.` + `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON. ` + 'OFF commands still sent to device.', ); device = this.deviceRegistry.getScene(decodedTopic.id); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 1748ca2..cd3abd7 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -142,7 +142,6 @@ class PlejBLEHandler extends EventEmitter { deviceId, BLE_CMD_DIM2_CHANGE, `01${brightnessVal.toString(16).padStart(4, '0')}`, - `Dim ${data}`, ); break; default: @@ -799,7 +798,9 @@ class PlejBLEHandler extends EventEmitter { try { this.write(payload); } catch (err) { - logger.error('Failed writing new time to Plejd. Will try again in one hour or at restart.'); + logger.error( + 'Failed writing new time to Plejd. Will try again in one hour or at restart.', + ); } } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 86ed5f8..888f4cb 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -88,12 +88,21 @@ class PlejdDeviceCommunication extends EventEmitter { }); } else if (command === COMMANDS.TURN_ON) { this.plejdDevices[deviceId] = { - state: data.state, + state: 1, dim: 0, }; logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { - state: data.state, + state: 1, + }); + } else if (command === COMMANDS.TURN_OFF) { + this.plejdDevices[deviceId] = { + state: 0, + dim: 0, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: 0, }); } else if (command === COMMANDS.TRIGGER_SCENE) { this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); @@ -237,7 +246,9 @@ class PlejdDeviceCommunication extends EventEmitter { logger.debug( `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${ queueItem.command - }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${this.writeQueue.length}`, + }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${ + this.writeQueue.length + }`, ); if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { From 0dbe0bb95fe1d06b5d735e04adfafb4f75d4494e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 12:34:30 +0100 Subject: [PATCH 06/22] Move BLE states to DeviceRegistry and improve logging - Make deviceRegistry states/lists immutable --- plejd/DeviceRegistry.js | 92 ++++++++++++++++++++++++++----- plejd/PlejdBLEHandler.js | 9 ++- plejd/PlejdDeviceCommunication.js | 19 +------ 3 files changed, 86 insertions(+), 34 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index 647e5bc..0a60c3d 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -1,3 +1,6 @@ +const Logger = require('./Logger'); + +const logger = Logger.getLogger('device-registry'); class DeviceRegistry { apiSite; cryptoKey = null; @@ -19,20 +22,56 @@ class DeviceRegistry { } addPlejdDevice(device) { - this.plejdDevices[device.id] = device; - this.deviceIdsBySerial[device.serialNumber] = device.id; - if (!this.deviceIdsByRoom[device.roomId]) { - this.deviceIdsByRoom[device.roomId] = []; + const added = { + ...this.plejdDevices[device.id], + ...device, + }; + + this.plejdDevices = { + ...this.plejdDevices, + [added.id]: added, + }; + + this.deviceIdsBySerial[added.serialNumber] = added.id; + + logger.verbose(`Added/updated device: ${JSON.stringify(added)}`); + + if (added.roomId) { + this.deviceIdsByRoom[added.roomId] = [ + ...(this.deviceIdsByRoom[added.roomId] || []), + added.id, + ]; + logger.verbose(`Added to room: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`); } - this.deviceIdsByRoom[device.roomId].push(device.id); + + return added; + } + + addRoomDevice(device) { + const added = { + ...this.roomDevices[device.id], + ...device, + }; + this.roomDevices = { + ...this.roomDevices, + [device.id]: added, + }; + + logger.verbose(`Added/updated room device: ${JSON.stringify(added)}`); + return added; } addScene(scene) { - this.sceneDevices[scene.id] = scene; - } - - setApiSite(siteDetails) { - this.apiSite = siteDetails; + const added = { + ...this.sceneDevices[scene.id], + ...scene, + }; + this.sceneDevices = { + ...this.sceneDevices, + added, + }; + logger.verbose(`Added/updated scene: ${JSON.stringify(added)}`); + return added; } clearPlejdDevices() { @@ -41,10 +80,6 @@ class DeviceRegistry { this.deviceIdsBySerial = {}; } - addRoomDevice(device) { - this.roomDevices[device.id] = device; - } - clearRoomDevices() { this.roomDevices = {}; } @@ -58,7 +93,7 @@ class DeviceRegistry { } getDeviceBySerialNumber(serialNumber) { - return this.plejdDevices[this.deviceIdsBySerial[serialNumber]]; + return this.getDevice(this.deviceIdsBySerial[serialNumber]); } getDeviceName(deviceId) { @@ -72,6 +107,33 @@ class DeviceRegistry { getSceneName(sceneId) { return (this.sceneDevices[sceneId] || {}).name; } + + getState(deviceId) { + const device = this.getDevice(deviceId) || {}; + if (device.dimmable) { + return { + state: device.state, + dim: device.dim, + }; + } + return { + state: device.state, + }; + } + + setApiSite(siteDetails) { + this.apiSite = siteDetails; + } + + setState(deviceId, state, dim) { + const device = this.addPlejdDevice({ id: deviceId, state }); + if (dim && device.dimmable) { + device.dim = dim; + } + if (Logger.shouldLog('silly')) { + logger.silly(`Updated state: ${JSON.stringify(device)}`); + } + } } module.exports = DeviceRegistry; diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index cd3abd7..92b1232 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -171,9 +171,12 @@ class PlejBLEHandler extends EventEmitter { fixedPlejdPath = fixedPlejdPath.replace(/_/g, ''); plejd.device = this.deviceRegistry.getDeviceBySerialNumber(fixedPlejdPath); - logger.debug(`Discovered ${plejd.path} with rssi ${plejd.rssi}, name ${plejd.device.name}`); - // Todo: Connect should probably be done here - this.bleDevices.push(plejd); + if (plejd.device) { + logger.debug(`Discovered ${plejd.path} with rssi ${plejd.rssi}, name ${plejd.device.name}`); + this.bleDevices.push(plejd); + } else { + logger.warn(`Device registry does not contain device with serial ${fixedPlejdPath}`); + } } catch (err) { logger.error(`Failed inspecting ${path}. `, err); } diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 888f4cb..9ce469c 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -15,7 +15,6 @@ class PlejdDeviceCommunication extends EventEmitter { plejdBleHandler; config; deviceRegistry; - plejdDevices = {}; // Todo: Move to deviceRegistry? writeQueue = []; writeQueueRef = null; @@ -77,30 +76,18 @@ class PlejdDeviceCommunication extends EventEmitter { _bleCommandReceived(deviceId, command, data) { try { if (command === COMMANDS.DIM) { - this.plejdDevices[deviceId] = { - state: data.state, - dim: data.dim, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.deviceRegistry.setState(deviceId, data.state, data.dim); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { state: data.state, brightness: data.dim, }); } else if (command === COMMANDS.TURN_ON) { - this.plejdDevices[deviceId] = { - state: 1, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.deviceRegistry.setState(deviceId, 1); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { state: 1, }); } else if (command === COMMANDS.TURN_OFF) { - this.plejdDevices[deviceId] = { - state: 0, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.deviceRegistry.setState(deviceId, 0); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { state: 0, }); From 50d664c9334e347b7f1cda292346e6f49dd26e54 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 15:33:06 +0100 Subject: [PATCH 07/22] Clean up events and subscriptions --- plejd/DeviceRegistry.js | 29 ++++++++++++---- plejd/MqttClient.js | 15 +++++++-- plejd/PlejdAddon.js | 56 ++++++++++++++++++++----------- plejd/PlejdBLEHandler.js | 27 ++++++++++++--- plejd/PlejdDeviceCommunication.js | 36 ++++++++++++-------- plejd/SceneManager.js | 5 +-- 6 files changed, 117 insertions(+), 51 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index 0a60c3d..e9c45c8 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -34,14 +34,20 @@ class DeviceRegistry { this.deviceIdsBySerial[added.serialNumber] = added.id; - logger.verbose(`Added/updated device: ${JSON.stringify(added)}`); + logger.verbose( + `Added/updated device: ${JSON.stringify(added)}. ${ + Object.keys(this.plejdDevices).length + } plejd devices in total.`, + ); if (added.roomId) { this.deviceIdsByRoom[added.roomId] = [ ...(this.deviceIdsByRoom[added.roomId] || []), added.id, ]; - logger.verbose(`Added to room: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`); + logger.verbose( + `Added to room #${added.roomId}: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`, + ); } return added; @@ -54,10 +60,14 @@ class DeviceRegistry { }; this.roomDevices = { ...this.roomDevices, - [device.id]: added, + [added.id]: added, }; - logger.verbose(`Added/updated room device: ${JSON.stringify(added)}`); + logger.verbose( + `Added/updated room device: ${JSON.stringify(added)}. ${ + Object.keys(this.roomDevices).length + } room devices total.`, + ); return added; } @@ -68,9 +78,13 @@ class DeviceRegistry { }; this.sceneDevices = { ...this.sceneDevices, - added, + [added.id]: added, }; - logger.verbose(`Added/updated scene: ${JSON.stringify(added)}`); + logger.verbose( + `Added/updated scene: ${JSON.stringify(added)}. ${ + Object.keys(this.sceneDevices).length + } scenes in total.`, + ); return added; } @@ -126,7 +140,8 @@ class DeviceRegistry { } setState(deviceId, state, dim) { - const device = this.addPlejdDevice({ id: deviceId, state }); + const device = this.getDevice(deviceId) || this.addPlejdDevice({ id: deviceId }); + device.state = state; if (dim && device.dimmable) { device.dim = dim; } diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index fa05a9d..3571951 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -70,6 +70,11 @@ const getSwitchPayload = (device) => ({ class MqttClient extends EventEmitter { deviceRegistry; + static EVENTS = { + connected: 'connected', + stateChanged: 'stateChanged', + }; + constructor(deviceRegistry) { super(); @@ -97,7 +102,7 @@ class MqttClient extends EventEmitter { logger.error('Unable to subscribe to status topics'); } - this.emit('connected'); + this.emit(MqttClient.EVENTS.connected); }); this.client.subscribe(getSubscribePath(), (err) => { @@ -115,7 +120,7 @@ class MqttClient extends EventEmitter { this.client.on('message', (topic, message) => { if (startTopics.includes(topic)) { logger.info('Home Assistant has started. lets do discovery.'); - this.emit('connected'); + this.emit(MqttClient.EVENTS.connected); } else { const decodedTopic = decodeTopic(topic); if (decodedTopic) { @@ -147,7 +152,7 @@ class MqttClient extends EventEmitter { ); if (device) { - this.emit('stateChanged', device, command); + this.emit(MqttClient.EVENTS.stateChanged, device, command); } else { logger.warn( `Device for topic ${topic} not found! Can happen if HA calls previously existing devices.`, @@ -181,6 +186,10 @@ class MqttClient extends EventEmitter { this.client.reconnect(); } + cleanup() { + this.client.removeAllListeners(); + } + disconnect(callback) { this.deviceRegistry.allDevices.forEach((device) => { this.client.publish(getAvailabilityTopic(device), 'offline'); diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 2fc9c72..0f3c6f2 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -17,6 +17,7 @@ class PlejdAddon extends EventEmitter { plejdApi; plejdDeviceCommunication; mqttClient; + processCleanupFunc; sceneManager; constructor() { @@ -31,19 +32,30 @@ class PlejdAddon extends EventEmitter { this.mqttClient = new MqttClient(this.deviceRegistry); } + cleanup() { + this.mqttClient.cleanup(); + this.mqttClient.removeAllListeners(); + this.plejdDeviceCommunication.cleanup(); + this.plejdDeviceCommunication.removeAllListeners(); + } + async init() { logger.info('Main Plejd addon init()...'); await this.plejdApi.init(); this.sceneManager.init(); + this.processCleanupFunc = () => { + this.cleanup(); + this.processCleanupFunc = () => {}; + this.mqttClient.disconnect(() => process.exit(0)); + }; + ['SIGINT', 'SIGHUP', 'SIGTERM'].forEach((signal) => { - process.on(signal, () => { - this.mqttClient.disconnect(() => process.exit(0)); - }); + process.on(signal, this.processCleanupFunc); }); - this.mqttClient.on('connected', () => { + this.mqttClient.on(MqttClient.EVENTS.connected, () => { try { logger.verbose('connected to mqtt.'); this.mqttClient.sendDiscoveryToHomeAssistant(); @@ -53,7 +65,7 @@ class PlejdAddon extends EventEmitter { }); // subscribe to changes from HA - this.mqttClient.on('stateChanged', (device, command) => { + this.mqttClient.on(MqttClient.EVENTS.stateChanged, (device, command) => { try { const deviceId = device.id; @@ -99,21 +111,27 @@ class PlejdAddon extends EventEmitter { this.mqttClient.init(); // subscribe to changes from Plejd - this.plejdDeviceCommunication.on('stateChanged', (deviceId, command) => { - try { - this.mqttClient.updateState(deviceId, command); - } catch (err) { - logger.error('Error in PlejdService.stateChanged callback in main.js', err); - } - }); + this.plejdDeviceCommunication.on( + PlejdDeviceCommunication.EVENTS.stateChanged, + (deviceId, command) => { + try { + this.mqttClient.updateState(deviceId, command); + } catch (err) { + logger.error('Error in PlejdService.stateChanged callback in main.js', err); + } + }, + ); - this.plejdDeviceCommunication.on('sceneTriggered', (deviceId, sceneId) => { - try { - this.mqttClient.sceneTriggered(sceneId); - } catch (err) { - logger.error('Error in PlejdService.sceneTriggered callback in main.js', err); - } - }); + this.plejdDeviceCommunication.on( + PlejdDeviceCommunication.EVENTS.sceneTriggered, + (deviceId, sceneId) => { + try { + this.mqttClient.sceneTriggered(sceneId); + } catch (err) { + logger.error('Error in PlejdService.sceneTriggered callback in main.js', err); + } + }, + ); await this.plejdDeviceCommunication.init(); logger.info('Main init done'); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 92b1232..195c627 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -62,6 +62,8 @@ class PlejBLEHandler extends EventEmitter { connected: 'connected', reconnecting: 'reconnecting', commandReceived: 'commandReceived', + writeFailed: 'writeFailed', + writeSuccess: 'writeSuccess', }; constructor(deviceRegistry) { @@ -80,14 +82,30 @@ class PlejBLEHandler extends EventEmitter { auth: null, ping: null, }; + } - this.on('writeFailed', (error) => this._onWriteFailed(error)); - this.on('writeSuccess', () => this._onWriteSuccess()); + cleanup() { + this.removeAllListeners(PlejBLEHandler.EVENTS.writeFailed); + this.removeAllListeners(PlejBLEHandler.EVENTS.writeSuccess); + + if (this.bus) { + this.bus.removeAllListeners('error'); + this.bus.removeAllListeners('connect'); + } + if (this.characteristics.lastDataProperties) { + this.characteristics.lastDataProperties.removeAllListeners('PropertiesChanged'); + } + if (this.objectManager) { + this.objectManager.removeAllListeners('InterfacesAdded'); + } } async init() { logger.info('init()'); + this.on(PlejBLEHandler.EVENTS.writeFailed, (error) => this._onWriteFailed(error)); + this.on(PlejBLEHandler.EVENTS.writeSuccess, () => this._onWriteSuccess()); + this.bus = dbus.systemBus(); this.bus.on('error', (err) => { // Uncaught error events will show UnhandledPromiseRejection logs @@ -276,6 +294,7 @@ class PlejBLEHandler extends EventEmitter { async _getInterface() { const bluez = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, '/'); + this.objectManager = await bluez.getInterface(DBUS_OM_INTERFACE); // We need to find the ble interface which implements the Adapter1 interface @@ -404,13 +423,12 @@ class PlejBLEHandler extends EventEmitter { async _onInterfacesAdded(path, interfaces) { logger.silly(`Interface added ${path}, inspecting...`); - // const [adapter, dev, service, characteristic] = path.split('/').slice(3); const interfaceKeys = Object.keys(interfaces); if (interfaceKeys.indexOf(BLUEZ_DEVICE_ID) > -1) { if (interfaces[BLUEZ_DEVICE_ID].UUIDs.value.indexOf(PLEJD_SERVICE) > -1) { logger.debug(`Found Plejd service on ${path}`); - + this.objectManager.removeAllListeners('InterfacesAdded'); await this._initDiscoveredPlejdDevice(path); } else { logger.error('Uh oh, no Plejd device!'); @@ -452,6 +470,7 @@ class PlejBLEHandler extends EventEmitter { // eslint-disable-next-line no-constant-condition while (true) { try { + this.cleanup(); await delay(5000); this.emit(PlejBLEHandler.EVENTS.reconnecting); logger.info('Reconnecting BLE...'); diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 9ce469c..6497e9b 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -30,22 +30,31 @@ class PlejdDeviceCommunication extends EventEmitter { this.plejdBleHandler = new PlejBLEHandler(deviceRegistry); this.config = Configuration.getOptions(); this.deviceRegistry = deviceRegistry; + } - // eslint-disable-next-line max-len - this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); - - this.plejdBleHandler.on('connected', () => { - logger.info('Bluetooth connected. Plejd BLE up and running!'); - this.startWriteQueue(); - }); - this.plejdBleHandler.on('reconnecting', () => { - logger.info('Bluetooth reconnecting...'); - clearTimeout(this.writeQueueRef); - }); + cleanup() { + this.plejdBleHandler.cleanup(); + this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.commandReceived); + this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.connected); + this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.reconnecting); } async init() { try { + // eslint-disable-next-line max-len + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); + + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.connected, () => { + logger.info('Bluetooth connected. Plejd BLE up and running!'); + logger.verbose('Starting writeQueue loop.'); + this.startWriteQueue(); + }); + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.reconnecting, () => { + logger.info('Bluetooth reconnecting...'); + logger.verbose('Stopping writeQueue loop until connection is established.'); + clearTimeout(this.writeQueueRef); + }); + await this.plejdBleHandler.init(); } catch (err) { logger.error('Failed init() of BLE. Starting reconnect loop.'); @@ -108,9 +117,8 @@ class PlejdDeviceCommunication extends EventEmitter { } _transitionTo(deviceId, targetBrightness, transition, deviceName) { - const initialBrightness = this.plejdDevices[deviceId] - ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim - : null; + const device = this.deviceRegistry.getDevice(deviceId); + const initialBrightness = device ? device.state && device.dim : null; this._clearDeviceTransitionTimer(deviceId); const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; diff --git a/plejd/SceneManager.js b/plejd/SceneManager.js index a30e58b..e5047cc 100644 --- a/plejd/SceneManager.js +++ b/plejd/SceneManager.js @@ -1,16 +1,13 @@ -const EventEmitter = require('events'); const Logger = require('./Logger'); const Scene = require('./Scene'); const logger = Logger.getLogger('scene-manager'); -class SceneManager extends EventEmitter { +class SceneManager { deviceRegistry; plejdBle; scenes; constructor(deviceRegistry, plejdBle) { - super(); - this.deviceRegistry = deviceRegistry; this.plejdBle = plejdBle; this.scenes = {}; From e8ab13aed33a005f4d6a94778f5cdeeb063d40ce Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 19:48:08 +0100 Subject: [PATCH 08/22] Remove redundant log row --- plejd/PlejdBLEHandler.js | 1 - 1 file changed, 1 deletion(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 195c627..c6ea2d8 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -540,7 +540,6 @@ class PlejBLEHandler extends EventEmitter { logger.error("'Method \"WriteValue\" doesn't exist'. Plejd device is probably disconnected."); errorIndicatesDisconnected = true; } - logger.verbose(`Made it ${errorIndicatesDisconnected} || ${this.consecutiveWriteFails >= 5}`); if (errorIndicatesDisconnected || this.consecutiveWriteFails >= 5) { logger.warn( From 4d5a4ddbe350cc8e3c0ea65853a15c2aec9c21dc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Mon, 22 Feb 2021 09:50:06 +0100 Subject: [PATCH 09/22] Stop write queue when BLE is not connected to avoid loosing commands - Set max retry count to 10 since BLE loop will set channel to disconnected after 5 retries (or known unrecoverable errors) --- plejd/DeviceRegistry.js | 8 +- plejd/MqttClient.js | 122 +++++++++++++++--------------- plejd/PlejdAddon.js | 8 +- plejd/PlejdBLEHandler.js | 14 ++-- plejd/PlejdDeviceCommunication.js | 28 ++++--- 5 files changed, 99 insertions(+), 81 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index e9c45c8..a3612ac 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -41,10 +41,10 @@ class DeviceRegistry { ); if (added.roomId) { - this.deviceIdsByRoom[added.roomId] = [ - ...(this.deviceIdsByRoom[added.roomId] || []), - added.id, - ]; + const room = this.deviceIdsByRoom[added.roomId] || []; + if (!room.includes(added.roomId)) { + this.deviceIdsByRoom[added.roomId] = [...room, added.roomId]; + } logger.verbose( `Added to room #${added.roomId}: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`, ); diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index 3571951..0369010 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -99,7 +99,7 @@ class MqttClient extends EventEmitter { this.client.subscribe(startTopics, (err) => { if (err) { - logger.error('Unable to subscribe to status topics'); + logger.error('Unable to subscribe to status topics', err); } this.emit(MqttClient.EVENTS.connected); @@ -118,66 +118,70 @@ class MqttClient extends EventEmitter { }); this.client.on('message', (topic, message) => { - if (startTopics.includes(topic)) { - logger.info('Home Assistant has started. lets do discovery.'); - this.emit(MqttClient.EVENTS.connected); - } else { - const decodedTopic = decodeTopic(topic); - if (decodedTopic) { - let device = this.deviceRegistry.getDevice(decodedTopic.id); - - const messageString = message.toString(); - const isJsonMessage = messageString.startsWith('{'); - const command = isJsonMessage ? JSON.parse(messageString) : messageString; - - if ( - !isJsonMessage - && messageString === 'ON' - && this.deviceRegistry.getScene(decodedTopic.id) - ) { - // Guess that id that got state command without dim value belongs to Scene, not Device - // This guess could very well be wrong depending on the installation... - logger.warn( - `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON. ` - + 'OFF commands still sent to device.', - ); - device = this.deviceRegistry.getScene(decodedTopic.id); - } - const deviceName = device ? device.name : ''; - - switch (decodedTopic.command) { - case 'set': - logger.verbose( - `Got mqtt SET command for ${decodedTopic.type}, ${deviceName} (${decodedTopic.id}): ${messageString}`, - ); - - if (device) { - this.emit(MqttClient.EVENTS.stateChanged, device, command); - } else { - logger.warn( - `Device for topic ${topic} not found! Can happen if HA calls previously existing devices.`, - ); - } - break; - case 'state': - case 'config': - case 'availability': - logger.verbose( - `Sent mqtt ${decodedTopic.command} command for ${ - decodedTopic.type - }, ${deviceName} (${decodedTopic.id}). ${ - decodedTopic.command === 'availability' ? messageString : '' - }`, - ); - break; - default: - logger.verbose(`Warning: Unknown command ${decodedTopic.command} in decoded topic`); - } + try { + if (startTopics.includes(topic)) { + logger.info('Home Assistant has started. lets do discovery.'); + this.emit(MqttClient.EVENTS.connected); } else { - logger.verbose( - `Warning: Got unrecognized mqtt command on '${topic}': ${message.toString()}`, - ); + const decodedTopic = decodeTopic(topic); + if (decodedTopic) { + let device = this.deviceRegistry.getDevice(decodedTopic.id); + + const messageString = message.toString(); + const isJsonMessage = messageString.startsWith('{'); + const command = isJsonMessage ? JSON.parse(messageString) : messageString; + + if ( + !isJsonMessage + && messageString === 'ON' + && this.deviceRegistry.getScene(decodedTopic.id) + ) { + // Guess that id that got state command without dim value belongs to Scene, not Device + // This guess could very well be wrong depending on the installation... + logger.warn( + `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON. ` + + 'OFF commands still sent to device.', + ); + device = this.deviceRegistry.getScene(decodedTopic.id); + } + const deviceName = device ? device.name : ''; + + switch (decodedTopic.command) { + case 'set': + logger.verbose( + `Got mqtt SET command for ${decodedTopic.type}, ${deviceName} (${decodedTopic.id}): ${messageString}`, + ); + + if (device) { + this.emit(MqttClient.EVENTS.stateChanged, device, command); + } else { + logger.warn( + `Device for topic ${topic} not found! Can happen if HA calls previously existing devices.`, + ); + } + break; + case 'state': + case 'config': + case 'availability': + logger.verbose( + `Sent mqtt ${decodedTopic.command} command for ${ + decodedTopic.type + }, ${deviceName} (${decodedTopic.id}). ${ + decodedTopic.command === 'availability' ? messageString : '' + }`, + ); + break; + default: + logger.verbose(`Warning: Unknown command ${decodedTopic.command} in decoded topic`); + } + } else { + logger.verbose( + `Warning: Got unrecognized mqtt command on '${topic}': ${message.toString()}`, + ); + } } + } catch (err) { + logger.error(`Error processing mqtt message on topic ${topic}`, err); } }); } diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 0f3c6f2..196d986 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -104,7 +104,7 @@ class PlejdAddon extends EventEmitter { this.plejdDeviceCommunication.turnOff(deviceId, commandObj); } } catch (err) { - logger.error('Error in MqttClient.stateChanged callback in main.js', err); + logger.error('Error in MqttClient.stateChanged callback', err); } }); @@ -117,18 +117,18 @@ class PlejdAddon extends EventEmitter { try { this.mqttClient.updateState(deviceId, command); } catch (err) { - logger.error('Error in PlejdService.stateChanged callback in main.js', err); + logger.error('Error in PlejdService.stateChanged callback', err); } }, ); this.plejdDeviceCommunication.on( PlejdDeviceCommunication.EVENTS.sceneTriggered, - (deviceId, sceneId) => { + (sceneId) => { try { this.mqttClient.sceneTriggered(sceneId); } catch (err) { - logger.error('Error in PlejdService.sceneTriggered callback in main.js', err); + logger.error('Error in PlejdService.sceneTriggered callback', err); } }, ); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index c6ea2d8..05375d8 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -85,6 +85,12 @@ class PlejBLEHandler extends EventEmitter { } cleanup() { + logger.verbose('cleanup() - Clearing ping interval and clock update timer'); + clearInterval(this.pingRef); + clearTimeout(this.requestCurrentPlejdTimeRef); + + logger.verbose('Removing listeners to write events, bus events and objectManager...'); + this.removeAllListeners(PlejBLEHandler.EVENTS.writeFailed); this.removeAllListeners(PlejBLEHandler.EVENTS.writeSuccess); @@ -456,23 +462,21 @@ class PlejBLEHandler extends EventEmitter { } async startReconnectPeriodicallyLoop() { - logger.verbose('startReconnectPeriodicallyLoop'); + logger.info('Starting reconnect loop...'); if (this.reconnectInProgress) { logger.debug('Reconnect already in progress. Skipping this call.'); return; } - clearInterval(this.pingRef); - clearTimeout(this.writeQueueRef); - clearTimeout(this.requestCurrentPlejdTimeRef); this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ // eslint-disable-next-line no-constant-condition while (true) { try { + logger.verbose('Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...'); this.cleanup(); - await delay(5000); this.emit(PlejBLEHandler.EVENTS.reconnecting); + await delay(5000); logger.info('Reconnecting BLE...'); await this.init(); break; diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 6497e9b..4fafb6c 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -8,9 +8,10 @@ const { COMMANDS } = constants; const logger = Logger.getLogger('device-comm'); const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting -const MAX_RETRY_COUNT = 5; // Could be made a setting +const MAX_RETRY_COUNT = 10; // Could be made a setting class PlejdDeviceCommunication extends EventEmitter { + bleConnected; bleDeviceTransitionTimers = {}; plejdBleHandler; config; @@ -33,6 +34,7 @@ class PlejdDeviceCommunication extends EventEmitter { } cleanup() { + Object.values(this.bleDeviceTransitionTimers).forEach((t) => clearTimeout(t)); this.plejdBleHandler.cleanup(); this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.commandReceived); this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.connected); @@ -41,17 +43,21 @@ class PlejdDeviceCommunication extends EventEmitter { async init() { try { + this.cleanup(); + this.bleConnected = false; // eslint-disable-next-line max-len this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); this.plejdBleHandler.on(PlejBLEHandler.EVENTS.connected, () => { logger.info('Bluetooth connected. Plejd BLE up and running!'); - logger.verbose('Starting writeQueue loop.'); - this.startWriteQueue(); + logger.verbose(`Starting writeQueue loop. Write queue length: ${this.writeQueue.length}`); + this.bleConnected = true; + this._startWriteQueue(); }); this.plejdBleHandler.on(PlejBLEHandler.EVENTS.reconnecting, () => { logger.info('Bluetooth reconnecting...'); - logger.verbose('Stopping writeQueue loop until connection is established.'); + logger.verbose(`Stopping writeQueue loop until connection is established. Write queue length: ${this.writeQueue.length}`); + this.bleConnected = false; clearTimeout(this.writeQueueRef); }); @@ -101,7 +107,7 @@ class PlejdDeviceCommunication extends EventEmitter { state: 0, }); } else if (command === COMMANDS.TRIGGER_SCENE) { - this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); + this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, data.sceneId); } else { logger.warn(`Unknown ble command ${command}`); } @@ -226,16 +232,20 @@ class PlejdDeviceCommunication extends EventEmitter { }); } - startWriteQueue() { + _startWriteQueue() { logger.info('startWriteQueue()'); clearTimeout(this.writeQueueRef); - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + this.writeQueueRef = setTimeout(() => this._runWriteQueue(), this.config.writeQueueWaitTime); } - async runWriteQueue() { + async _runWriteQueue() { try { while (this.writeQueue.length > 0) { + if (!this.bleConnected) { + logger.warn('BLE not connected, stopping write queue until connection is up again.'); + return; + } const queueItem = this.writeQueue.pop(); const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); logger.debug( @@ -285,7 +295,7 @@ class PlejdDeviceCommunication extends EventEmitter { logger.error('Error in writeQueue loop, values probably not written to Plejd', e); } - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + this.writeQueueRef = setTimeout(() => this._runWriteQueue(), this.config.writeQueueWaitTime); } } From 925ccba647e20a0cb4411606dcdbd9f89b7dc89c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 27 Feb 2021 09:57:29 +0100 Subject: [PATCH 10/22] Stop recreating the dbus.systemBus on retries (old instances are not disposed correctly by underlying code) --- plejd/PlejdAddon.js | 17 +++++++---------- plejd/PlejdBLEHandler.js | 31 +++++++++++++++++++++++++++++-- plejd/PlejdDeviceCommunication.js | 4 +++- 3 files changed, 39 insertions(+), 13 deletions(-) diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 196d986..eb39c50 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -122,16 +122,13 @@ class PlejdAddon extends EventEmitter { }, ); - this.plejdDeviceCommunication.on( - PlejdDeviceCommunication.EVENTS.sceneTriggered, - (sceneId) => { - try { - this.mqttClient.sceneTriggered(sceneId); - } catch (err) { - logger.error('Error in PlejdService.sceneTriggered callback', err); - } - }, - ); + this.plejdDeviceCommunication.on(PlejdDeviceCommunication.EVENTS.sceneTriggered, (sceneId) => { + try { + this.mqttClient.sceneTriggered(sceneId); + } catch (err) { + logger.error('Error in PlejdService.sceneTriggered callback', err); + } + }); await this.plejdDeviceCommunication.init(); logger.info('Main init done'); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 05375d8..6f68a76 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -53,6 +53,7 @@ class PlejBLEHandler extends EventEmitter { pingRef = null; requestCurrentPlejdTimeRef = null; reconnectInProgress = false; + emergencyReconnectTimeout = null; // Refer to BLE-states.md regarding the internal BLE/bluez state machine of Bluetooth states // These states refer to the state machine of this file @@ -82,6 +83,8 @@ class PlejBLEHandler extends EventEmitter { auth: null, ping: null, }; + + this.bus = dbus.systemBus(); } cleanup() { @@ -112,7 +115,6 @@ class PlejBLEHandler extends EventEmitter { this.on(PlejBLEHandler.EVENTS.writeFailed, (error) => this._onWriteFailed(error)); this.on(PlejBLEHandler.EVENTS.writeSuccess, () => this._onWriteSuccess()); - this.bus = dbus.systemBus(); this.bus.on('error', (err) => { // Uncaught error events will show UnhandledPromiseRejection logs logger.verbose(`dbus-next error event: ${err.message}`); @@ -290,6 +292,9 @@ class PlejBLEHandler extends EventEmitter { ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); this.emit(PlejBLEHandler.EVENTS.connected); + + clearTimeout(this.emergencyReconnectTimeout); + this.emergencyReconnectTimeout = null; } catch (err) { // This method is run on a timer, so errors can't e re-thrown. // Start reconnect loop if errors occur here @@ -463,10 +468,24 @@ class PlejBLEHandler extends EventEmitter { async startReconnectPeriodicallyLoop() { logger.info('Starting reconnect loop...'); - if (this.reconnectInProgress) { + clearTimeout(this.emergencyReconnectTimeout); + this.emergencyReconnectTimeout = null; + await this._startReconnectPeriodicallyLoopInternal(); + } + + async _startReconnectPeriodicallyLoopInternal() { + logger.verbose('Starting internal reconnect loop...'); + + if (this.reconnectInProgress && !this.emergencyReconnectTimeout) { logger.debug('Reconnect already in progress. Skipping this call.'); return; } + if (this.emergencyReconnectTimeout) { + logger.warn( + 'Restarting reconnect loop due to emergency reconnect timer elapsed. This should very rarely happen!', + ); + } + this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ @@ -476,6 +495,14 @@ class PlejBLEHandler extends EventEmitter { logger.verbose('Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...'); this.cleanup(); this.emit(PlejBLEHandler.EVENTS.reconnecting); + + // Emergency 2 minute timer if reconnect silently fails somewhere + clearTimeout(this.emergencyReconnectTimeout); + this.emergencyReconnectTimeout = setTimeout( + () => this._startReconnectPeriodicallyLoopInternal(), + 120 * 1000, + ); + await delay(5000); logger.info('Reconnecting BLE...'); await this.init(); diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 4fafb6c..e64c8cd 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -56,7 +56,9 @@ class PlejdDeviceCommunication extends EventEmitter { }); this.plejdBleHandler.on(PlejBLEHandler.EVENTS.reconnecting, () => { logger.info('Bluetooth reconnecting...'); - logger.verbose(`Stopping writeQueue loop until connection is established. Write queue length: ${this.writeQueue.length}`); + logger.verbose( + `Stopping writeQueue loop until connection is established. Write queue length: ${this.writeQueue.length}`, + ); this.bleConnected = false; clearTimeout(this.writeQueueRef); }); From 6855e03e68770ca80b343c954cf6ffc8f66c003e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 27 Feb 2021 13:46:41 +0100 Subject: [PATCH 11/22] Invoke power cycling of the BLE adapter every 10th reconnect attempt --- plejd/PlejdBLEHandler.js | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 6f68a76..58ea552 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -48,6 +48,7 @@ class PlejBLEHandler extends EventEmitter { bus = null; connectedDevice = null; consecutiveWriteFails; + consecutiveReconnectAttempts = 0; discoveryTimeout = null; plejdService = null; pingRef = null; @@ -291,6 +292,7 @@ class PlejBLEHandler extends EventEmitter { // invalidated (third param), ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); + this.consecutiveReconnectAttempts = 0; this.emit(PlejBLEHandler.EVENTS.connected); clearTimeout(this.emergencyReconnectTimeout); @@ -345,18 +347,21 @@ class PlejBLEHandler extends EventEmitter { } async _powerCycleAdapter() { + logger.verbose('Power cycling BLE adapter'); await this._powerOffAdapter(); await this._powerOnAdapter(); } async _powerOnAdapter() { + logger.verbose('Powering on BLE adapter and waiting 5 seconds'); await this.adapterProperties.Set(BLUEZ_ADAPTER_ID, 'Powered', new dbus.Variant('b', 1)); - await delay(1000); + await delay(5000); } async _powerOffAdapter() { + logger.verbose('Powering off BLE adapter and waiting 5 seconds'); await this.adapterProperties.Set(BLUEZ_ADAPTER_ID, 'Powered', new dbus.Variant('b', 0)); - await delay(1000); + await delay(5000); } async _cleanExistingConnections(managedObjects) { @@ -494,6 +499,19 @@ class PlejBLEHandler extends EventEmitter { try { logger.verbose('Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...'); this.cleanup(); + + this.consecutiveReconnectAttempts++; + if (this.consecutiveReconnectAttempts % 10 === 0) { + logger.warn( + `Tried reconnecting ${this.consecutiveReconnectAttempts} times. Try power cycling the BLE adapter every 10th time...`, + ); + await this._powerCycleAdapter(); + } else { + logger.verbose( + `Reconnect attempt ${this.consecutiveReconnectAttempts} in a row. Will power cycle every 10th time.`, + ); + } + this.emit(PlejBLEHandler.EVENTS.reconnecting); // Emergency 2 minute timer if reconnect silently fails somewhere From 55f0f60be980f091c75196617c051ae180d8c812 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 27 Feb 2021 16:41:05 +0100 Subject: [PATCH 12/22] Fix setting state for created Plejd room devices - when using includeRoomsAsLights setting --- plejd/DeviceRegistry.js | 6 +++++- plejd/MqttClient.js | 1 + plejd/PlejdApi.js | 9 ++++++--- 3 files changed, 12 insertions(+), 4 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index 647e5bc..39cb342 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -54,7 +54,11 @@ class DeviceRegistry { } getDevice(deviceId) { - return this.plejdDevices[deviceId]; + return this.plejdDevices[deviceId] || this.roomDevices[deviceId]; + } + + getDeviceIdsByRoom(roomId) { + return this.deviceIdsByRoom[roomId]; } getDeviceBySerialNumber(serialNumber) { diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index de0b09d..5c89ee9 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -138,6 +138,7 @@ class MqttClient extends EventEmitter { ); device = this.deviceRegistry.getScene(decodedTopic.id); } + const deviceName = device ? device.name : ''; switch (decodedTopic.command) { diff --git a/plejd/PlejdApi.js b/plejd/PlejdApi.js index 3803ea8..5272249 100644 --- a/plejd/PlejdApi.js +++ b/plejd/PlejdApi.js @@ -332,14 +332,17 @@ class PlejdApi { const { roomId } = room; const roomAddress = this.siteDetails.roomAddress[roomId]; + const deviceIdsByRoom = this.deviceRegistry.getDeviceIdsByRoom(roomId); + + const dimmable = deviceIdsByRoom + && deviceIdsByRoom.some((deviceId) => this.deviceRegistry.getDevice(deviceId).dimmable); + const newDevice = { id: roomAddress, name: room.title, type: 'light', typeName: 'Room', - dimmable: this.deviceIdsByRoom[roomId].some( - (deviceId) => this.plejdDevices[deviceId].dimmable, - ), + dimmable, }; this.deviceRegistry.addRoomDevice(newDevice); From e986c8b85a7e18e62bc7bf5a8a54ce70b455f7a5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 27 Feb 2021 16:41:20 +0100 Subject: [PATCH 13/22] Bump version to 0.6.2 --- plejd/CHANGELOG.md | 8 ++++++++ plejd/config.json | 2 +- 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/plejd/CHANGELOG.md b/plejd/CHANGELOG.md index 9200036..e15b399 100644 --- a/plejd/CHANGELOG.md +++ b/plejd/CHANGELOG.md @@ -1,5 +1,13 @@ # Changelog hassio-plejd Home Assistant Plejd addon +### [0.6.2](https://github.com/icanos/hassio-plejd/tree/0.6.2) (2021-02-27) + +[Full Changelog](https://github.com/icanos/hassio-plejd/compare/0.6.1...0.6.2) + +**Closed issues:** + +- Include rooms as lights does not work in 0.6.1 [\#169](https://github.com/icanos/hassio-plejd/issues/169) + ### [0.6.1](https://github.com/icanos/hassio-plejd/tree/0.6.1) (2021-02-20) [Full Changelog](https://github.com/icanos/hassio-plejd/compare/0.6.0...0.6.1) diff --git a/plejd/config.json b/plejd/config.json index 8deb919..eeeff6c 100644 --- a/plejd/config.json +++ b/plejd/config.json @@ -1,6 +1,6 @@ { "name": "Plejd", - "version": "0.6.1", + "version": "0.6.2", "slug": "plejd", "description": "Adds support for the Swedish home automation devices from Plejd.", "url": "https://github.com/icanos/hassio-plejd/", From b3adf221e22cbe756f29eb0f661cb4450154d1c6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Thu, 18 Feb 2021 22:24:20 +0100 Subject: [PATCH 14/22] Break out and structure creation of BLE command payloads --- plejd/PlejdBLEHandler.js | 130 +++++++++++++++++++++++++-------------- 1 file changed, 85 insertions(+), 45 deletions(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index bef0441..24f20dd 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -23,6 +23,9 @@ const BLE_CMD_SCENE_TRIG = 0x0021; const BLE_CMD_TIME_UPDATE = 0x001b; const BLE_BROADCAST_DEVICE_ID = 0x01; +const BLE_REQUEST_NO_RESPONSE = 0x0110; +const BLE_REQUEST_RESPONSE = 0x0102; +// const BLE_REQUEST_READ_VALUE = 0x0103; const BLUEZ_SERVICE_NAME = 'org.bluez'; const DBUS_OM_INTERFACE = 'org.freedesktop.DBus.ObjectManager'; @@ -498,19 +501,26 @@ class PlejBLEHandler extends EventEmitter { } _setBrightness(deviceId, brightness, shouldRetry, deviceName) { - let payload = null; - let log = ''; - if (!brightness && brightness !== 0) { logger.debug( `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, ); - payload = Buffer.from(`${deviceId.toString(16).padStart(2, '0')}0110009701`, 'hex'); - log = 'ON'; + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_STATE_CHANGE, + '01', + 'TurnOn', + shouldRetry, + ); } else if (brightness <= 0) { logger.debug(`Queueing turn off ${deviceId}`); - payload = Buffer.from(`${deviceId.toString(16).padStart(2, '0')}0110009700`, 'hex'); - log = 'OFF'; + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_STATE_CHANGE, + '00', + 'TurnOff', + shouldRetry, + ); } else { if (brightness > 255) { // eslint-disable-next-line no-param-reassign @@ -520,20 +530,14 @@ class PlejBLEHandler extends EventEmitter { logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); // eslint-disable-next-line no-bitwise const brightnessVal = (brightness << 8) | brightness; - payload = Buffer.from( - `${deviceId.toString(16).padStart(2, '0')}0110009801${brightnessVal - .toString(16) - .padStart(4, '0')}`, - 'hex', + this._appendHexPayloadToWriteQueue( + deviceId, + BLE_CMD_DIM2_CHANGE, + `01${brightnessVal.toString(16).padStart(4, '0')}`, + `Dim ${brightness}`, + shouldRetry, ); - log = `DIM ${brightness}`; } - this.writeQueue.unshift({ - deviceId, - log, - shouldRetry, - payload, - }); } async authenticate() { @@ -672,21 +676,20 @@ class PlejBLEHandler extends EventEmitter { } async _requestCurrentPlejdTime() { - logger.info('Requesting current Plejd clock time...'); + if (!this.connectedDevice) { + logger.warn('Cannot request current Plejd time, not connected.'); + return; + } + logger.info('Requesting current Plejd time...'); - // Eg: 0b0102001b: 0b: id, 0102: read, 001b: time - const payload = Buffer.from( - `${this.connectedDevice.id.toString(16).padStart(2, '0')}0102${BLE_CMD_TIME_UPDATE.toString( - 16, - ).padStart(4, '0')}`, - 'hex', + this._appendHexPayloadToWriteQueue( + this.connectedDevice.id, + BLE_CMD_TIME_UPDATE, + '', + 'RequestTime', + true, + BLE_REQUEST_RESPONSE, ); - this.writeQueue.unshift({ - deviceId: this.connectedDevice.id, - log: 'RequestTime', - shouldRetry: true, - payload, - }); setTimeout(() => this._requestCurrentPlejdTime(), 1000 * 3600); // Once per hour } @@ -936,7 +939,7 @@ class PlejBLEHandler extends EventEmitter { } else if (cmd === BLE_CMD_TIME_UPDATE) { const now = new Date(); // Guess Plejd timezone based on HA time zone - const offsetSecondsGuess = now.getTimezoneOffset() * 60; + const offsetSecondsGuess = now.getTimezoneOffset() * 60 + 250; // Todo: 4 min off // Plejd reports local unix timestamp adjust to local time zone const plejdTimestampUTC = (decoded.readInt32LE(5) + offsetSecondsGuess) * 1000; @@ -955,20 +958,16 @@ class PlejBLEHandler extends EventEmitter { `Plejd clock time off by more than 1 minute. Reported time: ${plejdTime.toString()}, diff ${diffSeconds} seconds. Time will be set hourly.`, ); if (this.connectedDevice && deviceId === this.connectedDevice.id) { + // Requested time sync by us const newLocalTimestamp = now.getTime() / 1000 - offsetSecondsGuess; logger.info(`Setting time to ${now.toString()}`); - const payload = Buffer.alloc(10); - // E.g: 00 0110 001b 38df2360 00 - // 00: set?, 0110: don't respond, 001b: time command, 38df236000: the time - payload.write('000110001b', 0, 'hex'); - payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5); - payload.write('00', 9, 'hex'); - this.writeQueue.unshift({ - deviceId: this.connectedDevice.id, - log: 'SetTime', - shouldRetry: true, - payload, - }); + this._appendPayloadToWriteQueue( + this.connectedDevice.id, + BLE_CMD_TIME_UPDATE, + 10, + (payload) => payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5), + 'SetTime', + ); } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { logger.info('Got time response. Plejd clock time in sync with Home Assistant time'); @@ -983,6 +982,47 @@ class PlejBLEHandler extends EventEmitter { } } + _appendHexPayloadToWriteQueue( + deviceId, + command, + hexDataString, + log, + shouldRetry = true, + requestResponseCommand = BLE_REQUEST_NO_RESPONSE, + ) { + this._appendPayloadToWriteQueue( + deviceId, + command, + 5 + Math.ceil(hexDataString.length / 2), + (payload) => payload.write(hexDataString, 5, 'hex'), + log, + shouldRetry, + requestResponseCommand, + ); + } + + _appendPayloadToWriteQueue( + deviceId, + command, + bufferLength, + payloadBufferAddDataFunc, + log, + shouldRetry = true, + requestResponseCommand = BLE_REQUEST_NO_RESPONSE, + ) { + const payload = Buffer.alloc(bufferLength); + payload.writeUInt8(deviceId); + payload.writeUInt16BE(requestResponseCommand, 1); + payload.writeUInt16BE(command, 3); + payloadBufferAddDataFunc(payload); + this.writeQueue.unshift({ + deviceId, + log, + shouldRetry, + payload, + }); + } + // eslint-disable-next-line class-methods-use-this _createChallengeResponse(key, challenge) { const intermediate = crypto.createHash('sha256').update(xor(key, challenge)).digest(); From fb48b1fd1fd7b098b98e8936cadec5df8bf79194 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 07:55:26 +0100 Subject: [PATCH 15/22] Split device communication and BLE handling into separate files --- plejd/Dockerfile | 12 +- plejd/PlejdAddon.js | 31 +-- plejd/PlejdBLEHandler.js | 379 ++++++++---------------------- plejd/PlejdDeviceCommunication.js | 286 ++++++++++++++++++++++ plejd/constants.js | 8 + 5 files changed, 405 insertions(+), 311 deletions(-) create mode 100644 plejd/PlejdDeviceCommunication.js create mode 100644 plejd/constants.js diff --git a/plejd/Dockerfile b/plejd/Dockerfile index 9f558a9..cb32527 100644 --- a/plejd/Dockerfile +++ b/plejd/Dockerfile @@ -7,19 +7,9 @@ ENV LANG C.UTF-8 SHELL ["/bin/bash", "-o", "pipefail", "-c"] # Copy data for add-on +COPY ./*.js /plejd/ COPY ./config.json /plejd/ -COPY ./Configuration.js /plejd/ -COPY ./DeviceRegistry.js /plejd/ -COPY ./Logger.js /plejd/ -COPY ./main.js /plejd/ -COPY ./MqttClient.js /plejd/ COPY ./package.json /plejd/ -COPY ./PlejdAddon.js /plejd/ -COPY ./PlejdApi.js /plejd/ -COPY ./PlejdBLEHandler.js /plejd/ -COPY ./Scene.js /plejd/ -COPY ./SceneManager.js /plejd/ -COPY ./SceneStep.js /plejd/ ARG BUILD_ARCH diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 9f2a18a..2fc9c72 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -3,8 +3,7 @@ const EventEmitter = require('events'); const Configuration = require('./Configuration'); const Logger = require('./Logger'); const PlejdApi = require('./PlejdApi'); -// const PlejdBLE = require('./PlejdBLE'); -const PlejdBLEHandler = require('./PlejdBLEHandler'); +const PlejdDeviceCommunication = require('./PlejdDeviceCommunication'); const MqttClient = require('./MqttClient'); const SceneManager = require('./SceneManager'); const DeviceRegistry = require('./DeviceRegistry'); @@ -16,7 +15,7 @@ class PlejdAddon extends EventEmitter { config; deviceRegistry; plejdApi; - plejdBLEHandler; + plejdDeviceCommunication; mqttClient; sceneManager; @@ -27,8 +26,8 @@ class PlejdAddon extends EventEmitter { this.deviceRegistry = new DeviceRegistry(); this.plejdApi = new PlejdApi(this.deviceRegistry); - this.plejdBLEHandler = new PlejdBLEHandler(this.deviceRegistry); - this.sceneManager = new SceneManager(this.deviceRegistry, this.plejdBLEHandler); + this.plejdDeviceCommunication = new PlejdDeviceCommunication(this.deviceRegistry); + this.sceneManager = new SceneManager(this.deviceRegistry, this.plejdDeviceCommunication); this.mqttClient = new MqttClient(this.deviceRegistry); } @@ -88,9 +87,9 @@ class PlejdAddon extends EventEmitter { } if (state === 'ON') { - this.plejdBLEHandler.turnOn(deviceId, commandObj); + this.plejdDeviceCommunication.turnOn(deviceId, commandObj); } else { - this.plejdBLEHandler.turnOff(deviceId, commandObj); + this.plejdDeviceCommunication.turnOff(deviceId, commandObj); } } catch (err) { logger.error('Error in MqttClient.stateChanged callback in main.js', err); @@ -99,15 +98,8 @@ class PlejdAddon extends EventEmitter { this.mqttClient.init(); - this.plejdBLEHandler.on('connected', () => { - logger.info('Bluetooth connected. Plejd BLE up and running!'); - }); - this.plejdBLEHandler.on('reconnecting', () => { - logger.info('Bluetooth reconnecting...'); - }); - // subscribe to changes from Plejd - this.plejdBLEHandler.on('stateChanged', (deviceId, command) => { + this.plejdDeviceCommunication.on('stateChanged', (deviceId, command) => { try { this.mqttClient.updateState(deviceId, command); } catch (err) { @@ -115,7 +107,7 @@ class PlejdAddon extends EventEmitter { } }); - this.plejdBLEHandler.on('sceneTriggered', (deviceId, sceneId) => { + this.plejdDeviceCommunication.on('sceneTriggered', (deviceId, sceneId) => { try { this.mqttClient.sceneTriggered(sceneId); } catch (err) { @@ -123,12 +115,7 @@ class PlejdAddon extends EventEmitter { } }); - try { - await this.plejdBLEHandler.init(); - } catch (err) { - logger.error('Failed init() of BLE. Starting reconnect loop.'); - await this.plejdBLEHandler.startReconnectPeriodicallyLoop(); - } + await this.plejdDeviceCommunication.init(); logger.info('Main init done'); } } diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 24f20dd..1748ca2 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -2,10 +2,12 @@ const dbus = require('dbus-next'); const crypto = require('crypto'); const xor = require('buffer-xor'); const EventEmitter = require('events'); -const Logger = require('./Logger'); const Configuration = require('./Configuration'); +const constants = require('./constants'); +const Logger = require('./Logger'); +const { COMMANDS } = constants; const logger = Logger.getLogger('plejd-ble'); // UUIDs @@ -36,9 +38,6 @@ const BLUEZ_DEVICE_ID = 'org.bluez.Device1'; const GATT_SERVICE_ID = 'org.bluez.GattService1'; const GATT_CHRC_ID = 'org.bluez.GattCharacteristic1'; -const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting -const MAX_RETRY_COUNT = 5; // Could be made a setting - const delay = (timeout) => new Promise((resolve) => setTimeout(resolve, timeout)); class PlejBLEHandler extends EventEmitter { @@ -46,24 +45,24 @@ class PlejBLEHandler extends EventEmitter { adapterProperties; config; bleDevices = []; - bleDeviceTransitionTimers = {}; bus = null; connectedDevice = null; consecutiveWriteFails; - deviceRegistry; discoveryTimeout = null; plejdService = null; - plejdDevices = {}; pingRef = null; - writeQueue = []; - writeQueueRef = null; + requestCurrentPlejdTimeRef = null; reconnectInProgress = false; // Refer to BLE-states.md regarding the internal BLE/bluez state machine of Bluetooth states // These states refer to the state machine of this file static STATES = ['MAIN_INIT', 'GET_ADAPTER_PROXY']; - static EVENTS = ['connected', 'reconnecting', 'sceneTriggered', 'stateChanged']; + static EVENTS = { + connected: 'connected', + reconnecting: 'reconnecting', + commandReceived: 'commandReceived', + }; constructor(deviceRegistry) { super(); @@ -82,8 +81,8 @@ class PlejBLEHandler extends EventEmitter { ping: null, }; - this.on('writeFailed', (error) => this.onWriteFailed(error)); - this.on('writeSuccess', () => this.onWriteSuccess()); + this.on('writeFailed', (error) => this._onWriteFailed(error)); + this.on('writeSuccess', () => this._onWriteSuccess()); } async init() { @@ -126,6 +125,33 @@ class PlejBLEHandler extends EventEmitter { logger.info('BLE init done, waiting for devices.'); } + async sendCommand(command, deviceId, data) { + let payload; + let brightnessVal; + switch (command) { + case COMMANDS.TURN_ON: + payload = this._createHexPayload(deviceId, BLE_CMD_STATE_CHANGE, '01'); + break; + case COMMANDS.TURN_OFF: + payload = this._createHexPayload(deviceId, BLE_CMD_STATE_CHANGE, '00'); + break; + case COMMANDS.DIM: + // eslint-disable-next-line no-bitwise + brightnessVal = (data << 8) | data; + payload = this._createHexPayload( + deviceId, + BLE_CMD_DIM2_CHANGE, + `01${brightnessVal.toString(16).padStart(4, '0')}`, + `Dim ${data}`, + ); + break; + default: + logger.error(`Unknown command ${command}`); + throw new Error(`Unknown command ${command}`); + } + await this._write(payload); + } + async _initDiscoveredPlejdDevice(path) { logger.debug(`initDiscoveredPlejdDevice(). Got ${path} device`); @@ -220,7 +246,6 @@ class PlejBLEHandler extends EventEmitter { } logger.info(`BLE Connected to ${this.connectedDevice.name}`); - this.emit('connected'); // Connected and authenticated, request current time and start ping if (this.config.updatePlejdClock) { @@ -228,8 +253,7 @@ class PlejBLEHandler extends EventEmitter { } else { logger.info('Plejd clock updates disabled in configuration.'); } - this.startPing(); - this.startWriteQueue(); + this._startPing(); // After we've authenticated, we need to hook up the event listener // for changes to lastData. @@ -237,8 +261,9 @@ class PlejBLEHandler extends EventEmitter { iface, properties, // invalidated (third param), - ) => this.onLastDataUpdated(iface, properties)); + ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); + this.emit(PlejBLEHandler.EVENTS.connected); } catch (err) { // This method is run on a timer, so errors can't e re-thrown. // Start reconnect loop if errors occur here @@ -342,7 +367,7 @@ class PlejBLEHandler extends EventEmitter { async _startGetPlejdDevice() { logger.verbose('Setting up interfacesAdded subscription and discovery filter'); - this.objectManager.on('InterfacesAdded', (path, interfaces) => this.onInterfacesAdded(path, interfaces)); + this.objectManager.on('InterfacesAdded', (path, interfaces) => this._onInterfacesAdded(path, interfaces)); this.adapter.SetDiscoveryFilter({ UUIDs: new dbus.Variant('as', [PLEJD_SERVICE]), @@ -375,7 +400,7 @@ class PlejBLEHandler extends EventEmitter { ); } - async onInterfacesAdded(path, interfaces) { + async _onInterfacesAdded(path, interfaces) { logger.silly(`Interface added ${path}, inspecting...`); // const [adapter, dev, service, characteristic] = path.split('/').slice(3); const interfaceKeys = Object.keys(interfaces); @@ -393,154 +418,7 @@ class PlejBLEHandler extends EventEmitter { } } - turnOn(deviceId, command) { - const deviceName = this.deviceRegistry.getDeviceName(deviceId); - logger.info( - `Plejd got turn on command for ${deviceName} (${deviceId}), brightness ${command.brightness}${ - command.transition ? `, transition: ${command.transition}` : '' - }`, - ); - this._transitionTo(deviceId, command.brightness, command.transition, deviceName); - } - - turnOff(deviceId, command) { - const deviceName = this.deviceRegistry.getDeviceName(deviceId); - logger.info( - `Plejd got turn off command for ${deviceName} (${deviceId})${ - command.transition ? `, transition: ${command.transition}` : '' - }`, - ); - this._transitionTo(deviceId, 0, command.transition, deviceName); - } - - _clearDeviceTransitionTimer(deviceId) { - if (this.bleDeviceTransitionTimers[deviceId]) { - clearInterval(this.bleDeviceTransitionTimers[deviceId]); - } - } - - _transitionTo(deviceId, targetBrightness, transition, deviceName) { - const initialBrightness = this.plejdDevices[deviceId] - ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim - : null; - this._clearDeviceTransitionTimer(deviceId); - - const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; - - if ( - transition > 1 - && isDimmable - && (initialBrightness || initialBrightness === 0) - && (targetBrightness || targetBrightness === 0) - && targetBrightness !== initialBrightness - ) { - // Transition time set, known initial and target brightness - // Calculate transition interval time based on delta brightness and max steps per second - // During transition, measure actual transition interval time and adjust stepping continously - // If transition <= 1 second, Plejd will do a better job - // than we can in transitioning so transitioning will be skipped - - const deltaBrightness = targetBrightness - initialBrightness; - const transitionSteps = Math.min( - Math.abs(deltaBrightness), - MAX_TRANSITION_STEPS_PER_SECOND * transition, - ); - const transitionInterval = (transition * 1000) / transitionSteps; - - logger.debug( - `transitioning from ${initialBrightness} to ${targetBrightness} ${ - transition ? `in ${transition} seconds` : '' - }.`, - ); - logger.verbose( - `delta brightness ${deltaBrightness}, steps ${transitionSteps}, interval ${transitionInterval} ms`, - ); - - const dtStart = new Date(); - - let nSteps = 0; - - this.bleDeviceTransitionTimers[deviceId] = setInterval(() => { - const tElapsedMs = new Date().getTime() - dtStart.getTime(); - let tElapsed = tElapsedMs / 1000; - - if (tElapsed > transition || tElapsed < 0) { - tElapsed = transition; - } - - let newBrightness = Math.round( - initialBrightness + (deltaBrightness * tElapsed) / transition, - ); - - if (tElapsed === transition) { - nSteps++; - this._clearDeviceTransitionTimer(deviceId); - newBrightness = targetBrightness; - logger.debug( - `Queueing finalize ${deviceName} (${deviceId}) transition from ${initialBrightness} to ${targetBrightness} in ${tElapsedMs}ms. Done steps ${nSteps}. Average interval ${ - tElapsedMs / (nSteps || 1) - } ms.`, - ); - this._setBrightness(deviceId, newBrightness, true, deviceName); - } else { - nSteps++; - logger.verbose( - `Queueing dim transition for ${deviceName} (${deviceId}) to ${newBrightness}. Total queue length ${this.writeQueue.length}`, - ); - this._setBrightness(deviceId, newBrightness, false, deviceName); - } - }, transitionInterval); - } else { - if (transition && isDimmable) { - logger.debug( - `Could not transition light change. Either initial value is unknown or change is too small. Requested from ${initialBrightness} to ${targetBrightness}`, - ); - } - this._setBrightness(deviceId, targetBrightness, true, deviceName); - } - } - - _setBrightness(deviceId, brightness, shouldRetry, deviceName) { - if (!brightness && brightness !== 0) { - logger.debug( - `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, - ); - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_STATE_CHANGE, - '01', - 'TurnOn', - shouldRetry, - ); - } else if (brightness <= 0) { - logger.debug(`Queueing turn off ${deviceId}`); - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_STATE_CHANGE, - '00', - 'TurnOff', - shouldRetry, - ); - } else { - if (brightness > 255) { - // eslint-disable-next-line no-param-reassign - brightness = 255; - } - - logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); - // eslint-disable-next-line no-bitwise - const brightnessVal = (brightness << 8) | brightness; - this._appendHexPayloadToWriteQueue( - deviceId, - BLE_CMD_DIM2_CHANGE, - `01${brightnessVal.toString(16).padStart(4, '0')}`, - `Dim ${brightness}`, - shouldRetry, - ); - } - } - - async authenticate() { + async _authenticate() { logger.info('authenticate()'); try { @@ -565,6 +443,7 @@ class PlejBLEHandler extends EventEmitter { } clearInterval(this.pingRef); clearTimeout(this.writeQueueRef); + clearTimeout(this.requestCurrentPlejdTimeRef); this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ @@ -572,7 +451,7 @@ class PlejBLEHandler extends EventEmitter { while (true) { try { await delay(5000); - this.emit('reconnecting'); + this.emit(PlejBLEHandler.EVENTS.reconnecting); logger.info('Reconnecting BLE...'); await this.init(); break; @@ -585,45 +464,46 @@ class PlejBLEHandler extends EventEmitter { this.reconnectInProgress = false; } - async write(data) { - if (!data || !this.plejdService || !this.characteristics.data) { + async _write(payload) { + if (!payload || !this.plejdService || !this.characteristics.data) { logger.debug('data, plejdService or characteristics not available. Cannot write()'); - return false; + throw new Error('data, plejdService or characteristics not available. Cannot write()'); } try { - logger.verbose(`Sending ${data.length} byte(s) of data to Plejd. ${data.toString('hex')}`); - const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); + logger.verbose( + `Sending ${payload.length} byte(s) of data to Plejd. ${payload.toString('hex')}`, + ); + const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, payload); await this.characteristics.data.WriteValue([...encryptedData], {}); - await this.onWriteSuccess(); - return true; + await this._onWriteSuccess(); } catch (err) { + await this._onWriteFailed(err); if (err.message === 'In Progress') { logger.debug("Write failed due to 'In progress' ", err); - } else { - logger.debug('Write failed ', err); + throw new Error("Write failed due to 'In progress'"); } - await this.onWriteFailed(err); - return false; + logger.debug('Write failed ', err); + throw new Error(`Write failed due to ${err.message}`); } } - startPing() { + _startPing() { logger.info('startPing()'); clearInterval(this.pingRef); this.pingRef = setInterval(async () => { logger.silly('ping'); - await this.ping(); + await this._ping(); }, 3000); } // eslint-disable-next-line class-methods-use-this - onWriteSuccess() { + _onWriteSuccess() { this.consecutiveWriteFails = 0; } - async onWriteFailed(error) { + async _onWriteFailed(error) { this.consecutiveWriteFails++; logger.debug(`onWriteFailed #${this.consecutiveWriteFails} in a row.`, error); logger.verbose(`Error message: ${error.message}`); @@ -649,7 +529,7 @@ class PlejBLEHandler extends EventEmitter { } } - async ping() { + async _ping() { logger.silly('ping()'); const ping = crypto.randomBytes(1); @@ -660,19 +540,19 @@ class PlejBLEHandler extends EventEmitter { pong = await this.characteristics.ping.ReadValue({}); } catch (err) { logger.verbose(`Error pinging Plejd, calling onWriteFailed... ${err.message}`); - await this.onWriteFailed(err); + await this._onWriteFailed(err); return; } // eslint-disable-next-line no-bitwise if (((ping[0] + 1) & 0xff) !== pong[0]) { logger.verbose('Plejd ping failed, pong contains wrong data. Calling onWriteFailed...'); - await this.onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`)); + await this._onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`)); return; } logger.silly(`pong: ${pong[0]}`); - await this.onWriteSuccess(); + await this._onWriteSuccess(); } async _requestCurrentPlejdTime() { @@ -682,65 +562,23 @@ class PlejBLEHandler extends EventEmitter { } logger.info('Requesting current Plejd time...'); - this._appendHexPayloadToWriteQueue( + const payload = this._createHexPayload( this.connectedDevice.id, BLE_CMD_TIME_UPDATE, '', - 'RequestTime', - true, BLE_REQUEST_RESPONSE, ); - setTimeout(() => this._requestCurrentPlejdTime(), 1000 * 3600); // Once per hour - } - - startWriteQueue() { - logger.info('startWriteQueue()'); - clearTimeout(this.writeQueueRef); - - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); - } - - async runWriteQueue() { try { - while (this.writeQueue.length > 0) { - const queueItem = this.writeQueue.pop(); - const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); - logger.debug( - `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${queueItem.log}. Total queue length: ${this.writeQueue.length}`, - ); - - if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { - logger.verbose( - `Skipping ${deviceName} (${queueItem.deviceId}) ` - + `${queueItem.log} due to more recent command in queue.`, - ); - // Skip commands if new ones exist for the same deviceId - // still process all messages in order - } else { - // eslint-disable-next-line no-await-in-loop - const success = await this.write(queueItem.payload); - if (!success && queueItem.shouldRetry) { - queueItem.retryCount = (queueItem.retryCount || 0) + 1; - logger.debug(`Will retry command, count failed so far ${queueItem.retryCount}`); - if (queueItem.retryCount <= MAX_RETRY_COUNT) { - this.writeQueue.push(queueItem); // Add back to top of queue to be processed next; - } else { - logger.error( - `Write queue: Exceeed max retry count (${MAX_RETRY_COUNT}) for ${deviceName} (${queueItem.deviceId}). Command ${queueItem.log} failed.`, - ); - break; - } - if (queueItem.retryCount > 1) { - break; // First retry directly, consecutive after writeQueueWaitTime ms - } - } - } - } - } catch (e) { - logger.error('Error in writeQueue loop, values probably not written to Plejd', e); + this._write(payload); + } catch (error) { + logger.warn('Failed requesting time update from Plejd'); } - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + clearTimeout(this.requestCurrentPlejdTimeRef); + this.requestCurrentPlejdTimeRef = setTimeout( + () => this._requestCurrentPlejdTime(), + 1000 * 3600, + ); // Once per hour } async _processPlejdService(path, characteristics) { @@ -848,13 +686,13 @@ class PlejBLEHandler extends EventEmitter { logger.info('Connected device is a Plejd device with the right characteristics.'); this.connectedDevice = device.device; - await this.authenticate(); + await this._authenticate(); return this.connectedDevice; } // eslint-disable-next-line no-unused-vars - async onLastDataUpdated(iface, properties) { + async _onLastDataUpdated(iface, properties) { if (iface !== GATT_CHRC_ID) { return; } @@ -869,8 +707,8 @@ class PlejBLEHandler extends EventEmitter { return; } - const data = value.value; - const decoded = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); + const encryptedData = value.value; + const decoded = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, encryptedData); if (decoded.length < 5) { if (Logger.shouldLog('debug')) { @@ -904,29 +742,18 @@ class PlejBLEHandler extends EventEmitter { ); } + let command; + let data = {}; if (cmd === BLE_CMD_DIM_CHANGE || cmd === BLE_CMD_DIM2_CHANGE) { logger.debug(`${deviceName} (${deviceId}) got state+dim update. S: ${state}, D: ${dim}`); - this.emit('stateChanged', deviceId, { - state, - brightness: dim, - }); - - this.plejdDevices[deviceId] = { - state, - dim, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + command = COMMANDS.DIM; + data = { state, dim }; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_STATE_CHANGE) { logger.debug(`${deviceName} (${deviceId}) got state update. S: ${state}`); - this.emit('stateChanged', deviceId, { - state, - }); - this.plejdDevices[deviceId] = { - state, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + command = state ? COMMANDS.TURN_ON : COMMANDS.TURN_OFF; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_SCENE_TRIG) { const sceneId = state; const sceneName = this.deviceRegistry.getSceneName(sceneId); @@ -935,7 +762,9 @@ class PlejBLEHandler extends EventEmitter { `${sceneName} (${sceneId}) scene triggered (device id ${deviceId}). Name can be misleading if there is a device with the same numeric id.`, ); - this.emit('sceneTriggered', deviceId, sceneId); + command = COMMANDS.TRIGGER_SCENE; + data = { sceneId }; + this.emit(PlejBLEHandler.EVENTS.commandReceived, deviceId, command, data); } else if (cmd === BLE_CMD_TIME_UPDATE) { const now = new Date(); // Guess Plejd timezone based on HA time zone @@ -961,13 +790,17 @@ class PlejBLEHandler extends EventEmitter { // Requested time sync by us const newLocalTimestamp = now.getTime() / 1000 - offsetSecondsGuess; logger.info(`Setting time to ${now.toString()}`); - this._appendPayloadToWriteQueue( + const payload = this._createPayload( this.connectedDevice.id, BLE_CMD_TIME_UPDATE, 10, - (payload) => payload.writeInt32LE(Math.trunc(newLocalTimestamp), 5), - 'SetTime', + (pl) => pl.writeInt32LE(Math.trunc(newLocalTimestamp), 5), ); + try { + this.write(payload); + } catch (err) { + logger.error('Failed writing new time to Plejd. Will try again in one hour or at restart.'); + } } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { logger.info('Got time response. Plejd clock time in sync with Home Assistant time'); @@ -982,32 +815,27 @@ class PlejBLEHandler extends EventEmitter { } } - _appendHexPayloadToWriteQueue( + _createHexPayload( deviceId, command, hexDataString, - log, - shouldRetry = true, requestResponseCommand = BLE_REQUEST_NO_RESPONSE, ) { - this._appendPayloadToWriteQueue( + return this._createPayload( deviceId, command, 5 + Math.ceil(hexDataString.length / 2), (payload) => payload.write(hexDataString, 5, 'hex'), - log, - shouldRetry, requestResponseCommand, ); } - _appendPayloadToWriteQueue( + // eslint-disable-next-line class-methods-use-this + _createPayload( deviceId, command, bufferLength, payloadBufferAddDataFunc, - log, - shouldRetry = true, requestResponseCommand = BLE_REQUEST_NO_RESPONSE, ) { const payload = Buffer.alloc(bufferLength); @@ -1015,12 +843,7 @@ class PlejBLEHandler extends EventEmitter { payload.writeUInt16BE(requestResponseCommand, 1); payload.writeUInt16BE(command, 3); payloadBufferAddDataFunc(payload); - this.writeQueue.unshift({ - deviceId, - log, - shouldRetry, - payload, - }); + return payload; } // eslint-disable-next-line class-methods-use-this diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js new file mode 100644 index 0000000..86ed5f8 --- /dev/null +++ b/plejd/PlejdDeviceCommunication.js @@ -0,0 +1,286 @@ +const EventEmitter = require('events'); +const Configuration = require('./Configuration'); +const constants = require('./constants'); +const Logger = require('./Logger'); +const PlejBLEHandler = require('./PlejdBLEHandler'); + +const { COMMANDS } = constants; +const logger = Logger.getLogger('device-comm'); + +const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting +const MAX_RETRY_COUNT = 5; // Could be made a setting + +class PlejdDeviceCommunication extends EventEmitter { + bleDeviceTransitionTimers = {}; + plejdBleHandler; + config; + deviceRegistry; + plejdDevices = {}; // Todo: Move to deviceRegistry? + writeQueue = []; + writeQueueRef = null; + + static EVENTS = { + sceneTriggered: 'sceneTriggered', + stateChanged: 'stateChanged', + }; + + constructor(deviceRegistry) { + super(); + logger.info('Starting Plejd communication handler.'); + + this.plejdBleHandler = new PlejBLEHandler(deviceRegistry); + this.config = Configuration.getOptions(); + this.deviceRegistry = deviceRegistry; + + // eslint-disable-next-line max-len + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); + + this.plejdBleHandler.on('connected', () => { + logger.info('Bluetooth connected. Plejd BLE up and running!'); + this.startWriteQueue(); + }); + this.plejdBleHandler.on('reconnecting', () => { + logger.info('Bluetooth reconnecting...'); + clearTimeout(this.writeQueueRef); + }); + } + + async init() { + try { + await this.plejdBleHandler.init(); + } catch (err) { + logger.error('Failed init() of BLE. Starting reconnect loop.'); + await this.plejdBleHandler.startReconnectPeriodicallyLoop(); + } + } + + turnOn(deviceId, command) { + const deviceName = this.deviceRegistry.getDeviceName(deviceId); + logger.info( + `Plejd got turn on command for ${deviceName} (${deviceId}), brightness ${command.brightness}${ + command.transition ? `, transition: ${command.transition}` : '' + }`, + ); + this._transitionTo(deviceId, command.brightness, command.transition, deviceName); + } + + turnOff(deviceId, command) { + const deviceName = this.deviceRegistry.getDeviceName(deviceId); + logger.info( + `Plejd got turn off command for ${deviceName} (${deviceId})${ + command.transition ? `, transition: ${command.transition}` : '' + }`, + ); + this._transitionTo(deviceId, 0, command.transition, deviceName); + } + + _bleCommandReceived(deviceId, command, data) { + try { + if (command === COMMANDS.DIM) { + this.plejdDevices[deviceId] = { + state: data.state, + dim: data.dim, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: data.state, + brightness: data.dim, + }); + } else if (command === COMMANDS.TURN_ON) { + this.plejdDevices[deviceId] = { + state: data.state, + dim: 0, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: data.state, + }); + } else if (command === COMMANDS.TRIGGER_SCENE) { + this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); + } else { + logger.warn(`Unknown ble command ${command}`); + } + } catch (error) { + logger.error('Error processing ble command', error); + } + } + + _clearDeviceTransitionTimer(deviceId) { + if (this.bleDeviceTransitionTimers[deviceId]) { + clearInterval(this.bleDeviceTransitionTimers[deviceId]); + } + } + + _transitionTo(deviceId, targetBrightness, transition, deviceName) { + const initialBrightness = this.plejdDevices[deviceId] + ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim + : null; + this._clearDeviceTransitionTimer(deviceId); + + const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; + + if ( + transition > 1 + && isDimmable + && (initialBrightness || initialBrightness === 0) + && (targetBrightness || targetBrightness === 0) + && targetBrightness !== initialBrightness + ) { + // Transition time set, known initial and target brightness + // Calculate transition interval time based on delta brightness and max steps per second + // During transition, measure actual transition interval time and adjust stepping continously + // If transition <= 1 second, Plejd will do a better job + // than we can in transitioning so transitioning will be skipped + + const deltaBrightness = targetBrightness - initialBrightness; + const transitionSteps = Math.min( + Math.abs(deltaBrightness), + MAX_TRANSITION_STEPS_PER_SECOND * transition, + ); + const transitionInterval = (transition * 1000) / transitionSteps; + + logger.debug( + `transitioning from ${initialBrightness} to ${targetBrightness} ${ + transition ? `in ${transition} seconds` : '' + }.`, + ); + logger.verbose( + `delta brightness ${deltaBrightness}, steps ${transitionSteps}, interval ${transitionInterval} ms`, + ); + + const dtStart = new Date(); + + let nSteps = 0; + + this.bleDeviceTransitionTimers[deviceId] = setInterval(() => { + const tElapsedMs = new Date().getTime() - dtStart.getTime(); + let tElapsed = tElapsedMs / 1000; + + if (tElapsed > transition || tElapsed < 0) { + tElapsed = transition; + } + + let newBrightness = Math.round( + initialBrightness + (deltaBrightness * tElapsed) / transition, + ); + + if (tElapsed === transition) { + nSteps++; + this._clearDeviceTransitionTimer(deviceId); + newBrightness = targetBrightness; + logger.debug( + `Queueing finalize ${deviceName} (${deviceId}) transition from ${initialBrightness} to ${targetBrightness} in ${tElapsedMs}ms. Done steps ${nSteps}. Average interval ${ + tElapsedMs / (nSteps || 1) + } ms.`, + ); + this._setBrightness(deviceId, newBrightness, true, deviceName); + } else { + nSteps++; + logger.verbose( + `Queueing dim transition for ${deviceName} (${deviceId}) to ${newBrightness}. Total queue length ${this.writeQueue.length}`, + ); + this._setBrightness(deviceId, newBrightness, false, deviceName); + } + }, transitionInterval); + } else { + if (transition && isDimmable) { + logger.debug( + `Could not transition light change. Either initial value is unknown or change is too small. Requested from ${initialBrightness} to ${targetBrightness}`, + ); + } + this._setBrightness(deviceId, targetBrightness, true, deviceName); + } + } + + _setBrightness(deviceId, brightness, shouldRetry, deviceName) { + if (!brightness && brightness !== 0) { + logger.debug( + `Queueing turn on ${deviceName} (${deviceId}). No brightness specified, setting DIM to previous.`, + ); + this._appendCommandToWriteQueue(deviceId, COMMANDS.TURN_ON, null, shouldRetry); + } else if (brightness <= 0) { + logger.debug(`Queueing turn off ${deviceId}`); + this._appendCommandToWriteQueue(deviceId, COMMANDS.TURN_OFF, null, shouldRetry); + } else { + if (brightness > 255) { + // eslint-disable-next-line no-param-reassign + brightness = 255; + } + + logger.debug(`Queueing ${deviceId} set brightness to ${brightness}`); + // eslint-disable-next-line no-bitwise + this._appendCommandToWriteQueue(deviceId, COMMANDS.DIM, brightness, shouldRetry); + } + } + + _appendCommandToWriteQueue(deviceId, command, data, shouldRetry) { + this.writeQueue.unshift({ + deviceId, + command, + data, + shouldRetry, + }); + } + + startWriteQueue() { + logger.info('startWriteQueue()'); + clearTimeout(this.writeQueueRef); + + this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + } + + async runWriteQueue() { + try { + while (this.writeQueue.length > 0) { + const queueItem = this.writeQueue.pop(); + const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); + logger.debug( + `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${ + queueItem.command + }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${this.writeQueue.length}`, + ); + + if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { + logger.verbose( + `Skipping ${deviceName} (${queueItem.deviceId}) ` + + `${queueItem.command} due to more recent command in queue.`, + ); + // Skip commands if new ones exist for the same deviceId + // still process all messages in order + } else { + /* eslint-disable no-await-in-loop */ + try { + await this.plejdBleHandler.sendCommand( + queueItem.command, + queueItem.deviceId, + queueItem.data, + ); + } catch (err) { + if (queueItem.shouldRetry) { + queueItem.retryCount = (queueItem.retryCount || 0) + 1; + logger.debug(`Will retry command, count failed so far ${queueItem.retryCount}`); + if (queueItem.retryCount <= MAX_RETRY_COUNT) { + this.writeQueue.push(queueItem); // Add back to top of queue to be processed next; + } else { + logger.error( + `Write queue: Exceeed max retry count (${MAX_RETRY_COUNT}) for ${deviceName} (${queueItem.deviceId}). Command ${queueItem.command} failed.`, + ); + break; + } + if (queueItem.retryCount > 1) { + break; // First retry directly, consecutive after writeQueueWaitTime ms + } + } + } + /* eslint-enable no-await-in-loop */ + } + } + } catch (e) { + logger.error('Error in writeQueue loop, values probably not written to Plejd', e); + } + + this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + } +} + +module.exports = PlejdDeviceCommunication; diff --git a/plejd/constants.js b/plejd/constants.js new file mode 100644 index 0000000..0b69b3a --- /dev/null +++ b/plejd/constants.js @@ -0,0 +1,8 @@ +const COMMANDS = { + TURN_ON: 'Turn on', + TURN_OFF: 'Turn off', + DIM: 'Dim', + TRIGGER_SCENE: 'Trigger scene', +}; + +module.exports = { COMMANDS }; From 8d259a768b222ef33b5d87869aa81ebf914a48c6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 10:49:00 +0100 Subject: [PATCH 16/22] Fix turn off and dim commands --- plejd/MqttClient.js | 2 +- plejd/PlejdBLEHandler.js | 5 +++-- plejd/PlejdDeviceCommunication.js | 17 ++++++++++++++--- 3 files changed, 18 insertions(+), 6 deletions(-) diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index 5c89ee9..797a96a 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -133,7 +133,7 @@ class MqttClient extends EventEmitter { // Guess that id that got state command without dim value belongs to Scene, not Device // This guess could very well be wrong depending on the installation... logger.warn( - `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON.` + `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON. ` + 'OFF commands still sent to device.', ); device = this.deviceRegistry.getScene(decodedTopic.id); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 1748ca2..cd3abd7 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -142,7 +142,6 @@ class PlejBLEHandler extends EventEmitter { deviceId, BLE_CMD_DIM2_CHANGE, `01${brightnessVal.toString(16).padStart(4, '0')}`, - `Dim ${data}`, ); break; default: @@ -799,7 +798,9 @@ class PlejBLEHandler extends EventEmitter { try { this.write(payload); } catch (err) { - logger.error('Failed writing new time to Plejd. Will try again in one hour or at restart.'); + logger.error( + 'Failed writing new time to Plejd. Will try again in one hour or at restart.', + ); } } } else if (deviceId !== BLE_BROADCAST_DEVICE_ID) { diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 86ed5f8..888f4cb 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -88,12 +88,21 @@ class PlejdDeviceCommunication extends EventEmitter { }); } else if (command === COMMANDS.TURN_ON) { this.plejdDevices[deviceId] = { - state: data.state, + state: 1, dim: 0, }; logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { - state: data.state, + state: 1, + }); + } else if (command === COMMANDS.TURN_OFF) { + this.plejdDevices[deviceId] = { + state: 0, + dim: 0, + }; + logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { + state: 0, }); } else if (command === COMMANDS.TRIGGER_SCENE) { this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); @@ -237,7 +246,9 @@ class PlejdDeviceCommunication extends EventEmitter { logger.debug( `Write queue: Processing ${deviceName} (${queueItem.deviceId}). Command ${ queueItem.command - }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${this.writeQueue.length}`, + }${queueItem.data ? ` ${queueItem.data}` : ''}. Total queue length: ${ + this.writeQueue.length + }`, ); if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { From 4d7de61e4282de82a80ef5186c9857e6c4f50b08 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 12:34:30 +0100 Subject: [PATCH 17/22] Move BLE states to DeviceRegistry and improve logging - Make deviceRegistry states/lists immutable --- plejd/DeviceRegistry.js | 92 ++++++++++++++++++++++++++----- plejd/PlejdBLEHandler.js | 9 ++- plejd/PlejdDeviceCommunication.js | 19 +------ 3 files changed, 86 insertions(+), 34 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index 39cb342..4230927 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -1,3 +1,6 @@ +const Logger = require('./Logger'); + +const logger = Logger.getLogger('device-registry'); class DeviceRegistry { apiSite; cryptoKey = null; @@ -19,20 +22,56 @@ class DeviceRegistry { } addPlejdDevice(device) { - this.plejdDevices[device.id] = device; - this.deviceIdsBySerial[device.serialNumber] = device.id; - if (!this.deviceIdsByRoom[device.roomId]) { - this.deviceIdsByRoom[device.roomId] = []; + const added = { + ...this.plejdDevices[device.id], + ...device, + }; + + this.plejdDevices = { + ...this.plejdDevices, + [added.id]: added, + }; + + this.deviceIdsBySerial[added.serialNumber] = added.id; + + logger.verbose(`Added/updated device: ${JSON.stringify(added)}`); + + if (added.roomId) { + this.deviceIdsByRoom[added.roomId] = [ + ...(this.deviceIdsByRoom[added.roomId] || []), + added.id, + ]; + logger.verbose(`Added to room: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`); } - this.deviceIdsByRoom[device.roomId].push(device.id); + + return added; + } + + addRoomDevice(device) { + const added = { + ...this.roomDevices[device.id], + ...device, + }; + this.roomDevices = { + ...this.roomDevices, + [device.id]: added, + }; + + logger.verbose(`Added/updated room device: ${JSON.stringify(added)}`); + return added; } addScene(scene) { - this.sceneDevices[scene.id] = scene; - } - - setApiSite(siteDetails) { - this.apiSite = siteDetails; + const added = { + ...this.sceneDevices[scene.id], + ...scene, + }; + this.sceneDevices = { + ...this.sceneDevices, + added, + }; + logger.verbose(`Added/updated scene: ${JSON.stringify(added)}`); + return added; } clearPlejdDevices() { @@ -41,10 +80,6 @@ class DeviceRegistry { this.deviceIdsBySerial = {}; } - addRoomDevice(device) { - this.roomDevices[device.id] = device; - } - clearRoomDevices() { this.roomDevices = {}; } @@ -62,7 +97,7 @@ class DeviceRegistry { } getDeviceBySerialNumber(serialNumber) { - return this.plejdDevices[this.deviceIdsBySerial[serialNumber]]; + return this.getDevice(this.deviceIdsBySerial[serialNumber]); } getDeviceName(deviceId) { @@ -76,6 +111,33 @@ class DeviceRegistry { getSceneName(sceneId) { return (this.sceneDevices[sceneId] || {}).name; } + + getState(deviceId) { + const device = this.getDevice(deviceId) || {}; + if (device.dimmable) { + return { + state: device.state, + dim: device.dim, + }; + } + return { + state: device.state, + }; + } + + setApiSite(siteDetails) { + this.apiSite = siteDetails; + } + + setState(deviceId, state, dim) { + const device = this.addPlejdDevice({ id: deviceId, state }); + if (dim && device.dimmable) { + device.dim = dim; + } + if (Logger.shouldLog('silly')) { + logger.silly(`Updated state: ${JSON.stringify(device)}`); + } + } } module.exports = DeviceRegistry; diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index cd3abd7..92b1232 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -171,9 +171,12 @@ class PlejBLEHandler extends EventEmitter { fixedPlejdPath = fixedPlejdPath.replace(/_/g, ''); plejd.device = this.deviceRegistry.getDeviceBySerialNumber(fixedPlejdPath); - logger.debug(`Discovered ${plejd.path} with rssi ${plejd.rssi}, name ${plejd.device.name}`); - // Todo: Connect should probably be done here - this.bleDevices.push(plejd); + if (plejd.device) { + logger.debug(`Discovered ${plejd.path} with rssi ${plejd.rssi}, name ${plejd.device.name}`); + this.bleDevices.push(plejd); + } else { + logger.warn(`Device registry does not contain device with serial ${fixedPlejdPath}`); + } } catch (err) { logger.error(`Failed inspecting ${path}. `, err); } diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 888f4cb..9ce469c 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -15,7 +15,6 @@ class PlejdDeviceCommunication extends EventEmitter { plejdBleHandler; config; deviceRegistry; - plejdDevices = {}; // Todo: Move to deviceRegistry? writeQueue = []; writeQueueRef = null; @@ -77,30 +76,18 @@ class PlejdDeviceCommunication extends EventEmitter { _bleCommandReceived(deviceId, command, data) { try { if (command === COMMANDS.DIM) { - this.plejdDevices[deviceId] = { - state: data.state, - dim: data.dim, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.deviceRegistry.setState(deviceId, data.state, data.dim); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { state: data.state, brightness: data.dim, }); } else if (command === COMMANDS.TURN_ON) { - this.plejdDevices[deviceId] = { - state: 1, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.deviceRegistry.setState(deviceId, 1); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { state: 1, }); } else if (command === COMMANDS.TURN_OFF) { - this.plejdDevices[deviceId] = { - state: 0, - dim: 0, - }; - logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); + this.deviceRegistry.setState(deviceId, 0); this.emit(PlejdDeviceCommunication.EVENTS.stateChanged, deviceId, { state: 0, }); From ca7a5cdd57cc0abab005d01dcff9779424c9e1e8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 15:33:06 +0100 Subject: [PATCH 18/22] Clean up events and subscriptions --- plejd/DeviceRegistry.js | 29 ++++++++++++---- plejd/MqttClient.js | 15 +++++++-- plejd/PlejdAddon.js | 56 ++++++++++++++++++++----------- plejd/PlejdBLEHandler.js | 27 ++++++++++++--- plejd/PlejdDeviceCommunication.js | 36 ++++++++++++-------- plejd/SceneManager.js | 5 +-- 6 files changed, 117 insertions(+), 51 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index 4230927..c451c63 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -34,14 +34,20 @@ class DeviceRegistry { this.deviceIdsBySerial[added.serialNumber] = added.id; - logger.verbose(`Added/updated device: ${JSON.stringify(added)}`); + logger.verbose( + `Added/updated device: ${JSON.stringify(added)}. ${ + Object.keys(this.plejdDevices).length + } plejd devices in total.`, + ); if (added.roomId) { this.deviceIdsByRoom[added.roomId] = [ ...(this.deviceIdsByRoom[added.roomId] || []), added.id, ]; - logger.verbose(`Added to room: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`); + logger.verbose( + `Added to room #${added.roomId}: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`, + ); } return added; @@ -54,10 +60,14 @@ class DeviceRegistry { }; this.roomDevices = { ...this.roomDevices, - [device.id]: added, + [added.id]: added, }; - logger.verbose(`Added/updated room device: ${JSON.stringify(added)}`); + logger.verbose( + `Added/updated room device: ${JSON.stringify(added)}. ${ + Object.keys(this.roomDevices).length + } room devices total.`, + ); return added; } @@ -68,9 +78,13 @@ class DeviceRegistry { }; this.sceneDevices = { ...this.sceneDevices, - added, + [added.id]: added, }; - logger.verbose(`Added/updated scene: ${JSON.stringify(added)}`); + logger.verbose( + `Added/updated scene: ${JSON.stringify(added)}. ${ + Object.keys(this.sceneDevices).length + } scenes in total.`, + ); return added; } @@ -130,7 +144,8 @@ class DeviceRegistry { } setState(deviceId, state, dim) { - const device = this.addPlejdDevice({ id: deviceId, state }); + const device = this.getDevice(deviceId) || this.addPlejdDevice({ id: deviceId }); + device.state = state; if (dim && device.dimmable) { device.dim = dim; } diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index 797a96a..36e3497 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -70,6 +70,11 @@ const getSwitchPayload = (device) => ({ class MqttClient extends EventEmitter { deviceRegistry; + static EVENTS = { + connected: 'connected', + stateChanged: 'stateChanged', + }; + constructor(deviceRegistry) { super(); @@ -97,7 +102,7 @@ class MqttClient extends EventEmitter { logger.error('Unable to subscribe to status topics'); } - this.emit('connected'); + this.emit(MqttClient.EVENTS.connected); }); this.client.subscribe(getSubscribePath(), (err) => { @@ -115,7 +120,7 @@ class MqttClient extends EventEmitter { this.client.on('message', (topic, message) => { if (startTopics.includes(topic)) { logger.info('Home Assistant has started. lets do discovery.'); - this.emit('connected'); + this.emit(MqttClient.EVENTS.connected); } else { const decodedTopic = decodeTopic(topic); if (decodedTopic) { @@ -148,7 +153,7 @@ class MqttClient extends EventEmitter { ); if (device) { - this.emit('stateChanged', device, command); + this.emit(MqttClient.EVENTS.stateChanged, device, command); } else { logger.warn( `Device for topic ${topic} not found! Can happen if HA calls previously existing devices.`, @@ -182,6 +187,10 @@ class MqttClient extends EventEmitter { this.client.reconnect(); } + cleanup() { + this.client.removeAllListeners(); + } + disconnect(callback) { this.deviceRegistry.allDevices.forEach((device) => { this.client.publish(getAvailabilityTopic(device), 'offline'); diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 2fc9c72..0f3c6f2 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -17,6 +17,7 @@ class PlejdAddon extends EventEmitter { plejdApi; plejdDeviceCommunication; mqttClient; + processCleanupFunc; sceneManager; constructor() { @@ -31,19 +32,30 @@ class PlejdAddon extends EventEmitter { this.mqttClient = new MqttClient(this.deviceRegistry); } + cleanup() { + this.mqttClient.cleanup(); + this.mqttClient.removeAllListeners(); + this.plejdDeviceCommunication.cleanup(); + this.plejdDeviceCommunication.removeAllListeners(); + } + async init() { logger.info('Main Plejd addon init()...'); await this.plejdApi.init(); this.sceneManager.init(); + this.processCleanupFunc = () => { + this.cleanup(); + this.processCleanupFunc = () => {}; + this.mqttClient.disconnect(() => process.exit(0)); + }; + ['SIGINT', 'SIGHUP', 'SIGTERM'].forEach((signal) => { - process.on(signal, () => { - this.mqttClient.disconnect(() => process.exit(0)); - }); + process.on(signal, this.processCleanupFunc); }); - this.mqttClient.on('connected', () => { + this.mqttClient.on(MqttClient.EVENTS.connected, () => { try { logger.verbose('connected to mqtt.'); this.mqttClient.sendDiscoveryToHomeAssistant(); @@ -53,7 +65,7 @@ class PlejdAddon extends EventEmitter { }); // subscribe to changes from HA - this.mqttClient.on('stateChanged', (device, command) => { + this.mqttClient.on(MqttClient.EVENTS.stateChanged, (device, command) => { try { const deviceId = device.id; @@ -99,21 +111,27 @@ class PlejdAddon extends EventEmitter { this.mqttClient.init(); // subscribe to changes from Plejd - this.plejdDeviceCommunication.on('stateChanged', (deviceId, command) => { - try { - this.mqttClient.updateState(deviceId, command); - } catch (err) { - logger.error('Error in PlejdService.stateChanged callback in main.js', err); - } - }); + this.plejdDeviceCommunication.on( + PlejdDeviceCommunication.EVENTS.stateChanged, + (deviceId, command) => { + try { + this.mqttClient.updateState(deviceId, command); + } catch (err) { + logger.error('Error in PlejdService.stateChanged callback in main.js', err); + } + }, + ); - this.plejdDeviceCommunication.on('sceneTriggered', (deviceId, sceneId) => { - try { - this.mqttClient.sceneTriggered(sceneId); - } catch (err) { - logger.error('Error in PlejdService.sceneTriggered callback in main.js', err); - } - }); + this.plejdDeviceCommunication.on( + PlejdDeviceCommunication.EVENTS.sceneTriggered, + (deviceId, sceneId) => { + try { + this.mqttClient.sceneTriggered(sceneId); + } catch (err) { + logger.error('Error in PlejdService.sceneTriggered callback in main.js', err); + } + }, + ); await this.plejdDeviceCommunication.init(); logger.info('Main init done'); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 92b1232..195c627 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -62,6 +62,8 @@ class PlejBLEHandler extends EventEmitter { connected: 'connected', reconnecting: 'reconnecting', commandReceived: 'commandReceived', + writeFailed: 'writeFailed', + writeSuccess: 'writeSuccess', }; constructor(deviceRegistry) { @@ -80,14 +82,30 @@ class PlejBLEHandler extends EventEmitter { auth: null, ping: null, }; + } - this.on('writeFailed', (error) => this._onWriteFailed(error)); - this.on('writeSuccess', () => this._onWriteSuccess()); + cleanup() { + this.removeAllListeners(PlejBLEHandler.EVENTS.writeFailed); + this.removeAllListeners(PlejBLEHandler.EVENTS.writeSuccess); + + if (this.bus) { + this.bus.removeAllListeners('error'); + this.bus.removeAllListeners('connect'); + } + if (this.characteristics.lastDataProperties) { + this.characteristics.lastDataProperties.removeAllListeners('PropertiesChanged'); + } + if (this.objectManager) { + this.objectManager.removeAllListeners('InterfacesAdded'); + } } async init() { logger.info('init()'); + this.on(PlejBLEHandler.EVENTS.writeFailed, (error) => this._onWriteFailed(error)); + this.on(PlejBLEHandler.EVENTS.writeSuccess, () => this._onWriteSuccess()); + this.bus = dbus.systemBus(); this.bus.on('error', (err) => { // Uncaught error events will show UnhandledPromiseRejection logs @@ -276,6 +294,7 @@ class PlejBLEHandler extends EventEmitter { async _getInterface() { const bluez = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, '/'); + this.objectManager = await bluez.getInterface(DBUS_OM_INTERFACE); // We need to find the ble interface which implements the Adapter1 interface @@ -404,13 +423,12 @@ class PlejBLEHandler extends EventEmitter { async _onInterfacesAdded(path, interfaces) { logger.silly(`Interface added ${path}, inspecting...`); - // const [adapter, dev, service, characteristic] = path.split('/').slice(3); const interfaceKeys = Object.keys(interfaces); if (interfaceKeys.indexOf(BLUEZ_DEVICE_ID) > -1) { if (interfaces[BLUEZ_DEVICE_ID].UUIDs.value.indexOf(PLEJD_SERVICE) > -1) { logger.debug(`Found Plejd service on ${path}`); - + this.objectManager.removeAllListeners('InterfacesAdded'); await this._initDiscoveredPlejdDevice(path); } else { logger.error('Uh oh, no Plejd device!'); @@ -452,6 +470,7 @@ class PlejBLEHandler extends EventEmitter { // eslint-disable-next-line no-constant-condition while (true) { try { + this.cleanup(); await delay(5000); this.emit(PlejBLEHandler.EVENTS.reconnecting); logger.info('Reconnecting BLE...'); diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 9ce469c..6497e9b 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -30,22 +30,31 @@ class PlejdDeviceCommunication extends EventEmitter { this.plejdBleHandler = new PlejBLEHandler(deviceRegistry); this.config = Configuration.getOptions(); this.deviceRegistry = deviceRegistry; + } - // eslint-disable-next-line max-len - this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); - - this.plejdBleHandler.on('connected', () => { - logger.info('Bluetooth connected. Plejd BLE up and running!'); - this.startWriteQueue(); - }); - this.plejdBleHandler.on('reconnecting', () => { - logger.info('Bluetooth reconnecting...'); - clearTimeout(this.writeQueueRef); - }); + cleanup() { + this.plejdBleHandler.cleanup(); + this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.commandReceived); + this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.connected); + this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.reconnecting); } async init() { try { + // eslint-disable-next-line max-len + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); + + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.connected, () => { + logger.info('Bluetooth connected. Plejd BLE up and running!'); + logger.verbose('Starting writeQueue loop.'); + this.startWriteQueue(); + }); + this.plejdBleHandler.on(PlejBLEHandler.EVENTS.reconnecting, () => { + logger.info('Bluetooth reconnecting...'); + logger.verbose('Stopping writeQueue loop until connection is established.'); + clearTimeout(this.writeQueueRef); + }); + await this.plejdBleHandler.init(); } catch (err) { logger.error('Failed init() of BLE. Starting reconnect loop.'); @@ -108,9 +117,8 @@ class PlejdDeviceCommunication extends EventEmitter { } _transitionTo(deviceId, targetBrightness, transition, deviceName) { - const initialBrightness = this.plejdDevices[deviceId] - ? this.plejdDevices[deviceId].state && this.plejdDevices[deviceId].dim - : null; + const device = this.deviceRegistry.getDevice(deviceId); + const initialBrightness = device ? device.state && device.dim : null; this._clearDeviceTransitionTimer(deviceId); const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; diff --git a/plejd/SceneManager.js b/plejd/SceneManager.js index a30e58b..e5047cc 100644 --- a/plejd/SceneManager.js +++ b/plejd/SceneManager.js @@ -1,16 +1,13 @@ -const EventEmitter = require('events'); const Logger = require('./Logger'); const Scene = require('./Scene'); const logger = Logger.getLogger('scene-manager'); -class SceneManager extends EventEmitter { +class SceneManager { deviceRegistry; plejdBle; scenes; constructor(deviceRegistry, plejdBle) { - super(); - this.deviceRegistry = deviceRegistry; this.plejdBle = plejdBle; this.scenes = {}; From 4591af57b905627ef913f0a3d76ce4feb4bb2ad3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 20 Feb 2021 19:48:08 +0100 Subject: [PATCH 19/22] Remove redundant log row --- plejd/PlejdBLEHandler.js | 1 - 1 file changed, 1 deletion(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 195c627..c6ea2d8 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -540,7 +540,6 @@ class PlejBLEHandler extends EventEmitter { logger.error("'Method \"WriteValue\" doesn't exist'. Plejd device is probably disconnected."); errorIndicatesDisconnected = true; } - logger.verbose(`Made it ${errorIndicatesDisconnected} || ${this.consecutiveWriteFails >= 5}`); if (errorIndicatesDisconnected || this.consecutiveWriteFails >= 5) { logger.warn( From e7b8a5a82a07cb1af9bb2290ee63c47abc1471d6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Mon, 22 Feb 2021 09:50:06 +0100 Subject: [PATCH 20/22] Stop write queue when BLE is not connected to avoid loosing commands - Set max retry count to 10 since BLE loop will set channel to disconnected after 5 retries (or known unrecoverable errors) --- plejd/DeviceRegistry.js | 8 +- plejd/MqttClient.js | 123 +++++++++++++++--------------- plejd/PlejdAddon.js | 8 +- plejd/PlejdBLEHandler.js | 14 ++-- plejd/PlejdDeviceCommunication.js | 28 ++++--- 5 files changed, 99 insertions(+), 82 deletions(-) diff --git a/plejd/DeviceRegistry.js b/plejd/DeviceRegistry.js index c451c63..c03d969 100644 --- a/plejd/DeviceRegistry.js +++ b/plejd/DeviceRegistry.js @@ -41,10 +41,10 @@ class DeviceRegistry { ); if (added.roomId) { - this.deviceIdsByRoom[added.roomId] = [ - ...(this.deviceIdsByRoom[added.roomId] || []), - added.id, - ]; + const room = this.deviceIdsByRoom[added.roomId] || []; + if (!room.includes(added.roomId)) { + this.deviceIdsByRoom[added.roomId] = [...room, added.roomId]; + } logger.verbose( `Added to room #${added.roomId}: ${JSON.stringify(this.deviceIdsByRoom[added.roomId])}`, ); diff --git a/plejd/MqttClient.js b/plejd/MqttClient.js index 36e3497..0369010 100644 --- a/plejd/MqttClient.js +++ b/plejd/MqttClient.js @@ -99,7 +99,7 @@ class MqttClient extends EventEmitter { this.client.subscribe(startTopics, (err) => { if (err) { - logger.error('Unable to subscribe to status topics'); + logger.error('Unable to subscribe to status topics', err); } this.emit(MqttClient.EVENTS.connected); @@ -118,67 +118,70 @@ class MqttClient extends EventEmitter { }); this.client.on('message', (topic, message) => { - if (startTopics.includes(topic)) { - logger.info('Home Assistant has started. lets do discovery.'); - this.emit(MqttClient.EVENTS.connected); - } else { - const decodedTopic = decodeTopic(topic); - if (decodedTopic) { - let device = this.deviceRegistry.getDevice(decodedTopic.id); - - const messageString = message.toString(); - const isJsonMessage = messageString.startsWith('{'); - const command = isJsonMessage ? JSON.parse(messageString) : messageString; - - if ( - !isJsonMessage - && messageString === 'ON' - && this.deviceRegistry.getScene(decodedTopic.id) - ) { - // Guess that id that got state command without dim value belongs to Scene, not Device - // This guess could very well be wrong depending on the installation... - logger.warn( - `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON. ` - + 'OFF commands still sent to device.', - ); - device = this.deviceRegistry.getScene(decodedTopic.id); - } - - const deviceName = device ? device.name : ''; - - switch (decodedTopic.command) { - case 'set': - logger.verbose( - `Got mqtt SET command for ${decodedTopic.type}, ${deviceName} (${decodedTopic.id}): ${messageString}`, - ); - - if (device) { - this.emit(MqttClient.EVENTS.stateChanged, device, command); - } else { - logger.warn( - `Device for topic ${topic} not found! Can happen if HA calls previously existing devices.`, - ); - } - break; - case 'state': - case 'config': - case 'availability': - logger.verbose( - `Sent mqtt ${decodedTopic.command} command for ${ - decodedTopic.type - }, ${deviceName} (${decodedTopic.id}). ${ - decodedTopic.command === 'availability' ? messageString : '' - }`, - ); - break; - default: - logger.verbose(`Warning: Unknown command ${decodedTopic.command} in decoded topic`); - } + try { + if (startTopics.includes(topic)) { + logger.info('Home Assistant has started. lets do discovery.'); + this.emit(MqttClient.EVENTS.connected); } else { - logger.verbose( - `Warning: Got unrecognized mqtt command on '${topic}': ${message.toString()}`, - ); + const decodedTopic = decodeTopic(topic); + if (decodedTopic) { + let device = this.deviceRegistry.getDevice(decodedTopic.id); + + const messageString = message.toString(); + const isJsonMessage = messageString.startsWith('{'); + const command = isJsonMessage ? JSON.parse(messageString) : messageString; + + if ( + !isJsonMessage + && messageString === 'ON' + && this.deviceRegistry.getScene(decodedTopic.id) + ) { + // Guess that id that got state command without dim value belongs to Scene, not Device + // This guess could very well be wrong depending on the installation... + logger.warn( + `Device id ${decodedTopic.id} belongs to both scene and device, guessing Scene is what should be set to ON. ` + + 'OFF commands still sent to device.', + ); + device = this.deviceRegistry.getScene(decodedTopic.id); + } + const deviceName = device ? device.name : ''; + + switch (decodedTopic.command) { + case 'set': + logger.verbose( + `Got mqtt SET command for ${decodedTopic.type}, ${deviceName} (${decodedTopic.id}): ${messageString}`, + ); + + if (device) { + this.emit(MqttClient.EVENTS.stateChanged, device, command); + } else { + logger.warn( + `Device for topic ${topic} not found! Can happen if HA calls previously existing devices.`, + ); + } + break; + case 'state': + case 'config': + case 'availability': + logger.verbose( + `Sent mqtt ${decodedTopic.command} command for ${ + decodedTopic.type + }, ${deviceName} (${decodedTopic.id}). ${ + decodedTopic.command === 'availability' ? messageString : '' + }`, + ); + break; + default: + logger.verbose(`Warning: Unknown command ${decodedTopic.command} in decoded topic`); + } + } else { + logger.verbose( + `Warning: Got unrecognized mqtt command on '${topic}': ${message.toString()}`, + ); + } } + } catch (err) { + logger.error(`Error processing mqtt message on topic ${topic}`, err); } }); } diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 0f3c6f2..196d986 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -104,7 +104,7 @@ class PlejdAddon extends EventEmitter { this.plejdDeviceCommunication.turnOff(deviceId, commandObj); } } catch (err) { - logger.error('Error in MqttClient.stateChanged callback in main.js', err); + logger.error('Error in MqttClient.stateChanged callback', err); } }); @@ -117,18 +117,18 @@ class PlejdAddon extends EventEmitter { try { this.mqttClient.updateState(deviceId, command); } catch (err) { - logger.error('Error in PlejdService.stateChanged callback in main.js', err); + logger.error('Error in PlejdService.stateChanged callback', err); } }, ); this.plejdDeviceCommunication.on( PlejdDeviceCommunication.EVENTS.sceneTriggered, - (deviceId, sceneId) => { + (sceneId) => { try { this.mqttClient.sceneTriggered(sceneId); } catch (err) { - logger.error('Error in PlejdService.sceneTriggered callback in main.js', err); + logger.error('Error in PlejdService.sceneTriggered callback', err); } }, ); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index c6ea2d8..05375d8 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -85,6 +85,12 @@ class PlejBLEHandler extends EventEmitter { } cleanup() { + logger.verbose('cleanup() - Clearing ping interval and clock update timer'); + clearInterval(this.pingRef); + clearTimeout(this.requestCurrentPlejdTimeRef); + + logger.verbose('Removing listeners to write events, bus events and objectManager...'); + this.removeAllListeners(PlejBLEHandler.EVENTS.writeFailed); this.removeAllListeners(PlejBLEHandler.EVENTS.writeSuccess); @@ -456,23 +462,21 @@ class PlejBLEHandler extends EventEmitter { } async startReconnectPeriodicallyLoop() { - logger.verbose('startReconnectPeriodicallyLoop'); + logger.info('Starting reconnect loop...'); if (this.reconnectInProgress) { logger.debug('Reconnect already in progress. Skipping this call.'); return; } - clearInterval(this.pingRef); - clearTimeout(this.writeQueueRef); - clearTimeout(this.requestCurrentPlejdTimeRef); this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ // eslint-disable-next-line no-constant-condition while (true) { try { + logger.verbose('Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...'); this.cleanup(); - await delay(5000); this.emit(PlejBLEHandler.EVENTS.reconnecting); + await delay(5000); logger.info('Reconnecting BLE...'); await this.init(); break; diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 6497e9b..4fafb6c 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -8,9 +8,10 @@ const { COMMANDS } = constants; const logger = Logger.getLogger('device-comm'); const MAX_TRANSITION_STEPS_PER_SECOND = 5; // Could be made a setting -const MAX_RETRY_COUNT = 5; // Could be made a setting +const MAX_RETRY_COUNT = 10; // Could be made a setting class PlejdDeviceCommunication extends EventEmitter { + bleConnected; bleDeviceTransitionTimers = {}; plejdBleHandler; config; @@ -33,6 +34,7 @@ class PlejdDeviceCommunication extends EventEmitter { } cleanup() { + Object.values(this.bleDeviceTransitionTimers).forEach((t) => clearTimeout(t)); this.plejdBleHandler.cleanup(); this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.commandReceived); this.plejdBleHandler.removeAllListeners(PlejBLEHandler.EVENTS.connected); @@ -41,17 +43,21 @@ class PlejdDeviceCommunication extends EventEmitter { async init() { try { + this.cleanup(); + this.bleConnected = false; // eslint-disable-next-line max-len this.plejdBleHandler.on(PlejBLEHandler.EVENTS.commandReceived, (deviceId, command, data) => this._bleCommandReceived(deviceId, command, data)); this.plejdBleHandler.on(PlejBLEHandler.EVENTS.connected, () => { logger.info('Bluetooth connected. Plejd BLE up and running!'); - logger.verbose('Starting writeQueue loop.'); - this.startWriteQueue(); + logger.verbose(`Starting writeQueue loop. Write queue length: ${this.writeQueue.length}`); + this.bleConnected = true; + this._startWriteQueue(); }); this.plejdBleHandler.on(PlejBLEHandler.EVENTS.reconnecting, () => { logger.info('Bluetooth reconnecting...'); - logger.verbose('Stopping writeQueue loop until connection is established.'); + logger.verbose(`Stopping writeQueue loop until connection is established. Write queue length: ${this.writeQueue.length}`); + this.bleConnected = false; clearTimeout(this.writeQueueRef); }); @@ -101,7 +107,7 @@ class PlejdDeviceCommunication extends EventEmitter { state: 0, }); } else if (command === COMMANDS.TRIGGER_SCENE) { - this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, deviceId, data.sceneId); + this.emit(PlejdDeviceCommunication.EVENTS.sceneTriggered, data.sceneId); } else { logger.warn(`Unknown ble command ${command}`); } @@ -226,16 +232,20 @@ class PlejdDeviceCommunication extends EventEmitter { }); } - startWriteQueue() { + _startWriteQueue() { logger.info('startWriteQueue()'); clearTimeout(this.writeQueueRef); - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + this.writeQueueRef = setTimeout(() => this._runWriteQueue(), this.config.writeQueueWaitTime); } - async runWriteQueue() { + async _runWriteQueue() { try { while (this.writeQueue.length > 0) { + if (!this.bleConnected) { + logger.warn('BLE not connected, stopping write queue until connection is up again.'); + return; + } const queueItem = this.writeQueue.pop(); const deviceName = this.deviceRegistry.getDeviceName(queueItem.deviceId); logger.debug( @@ -285,7 +295,7 @@ class PlejdDeviceCommunication extends EventEmitter { logger.error('Error in writeQueue loop, values probably not written to Plejd', e); } - this.writeQueueRef = setTimeout(() => this.runWriteQueue(), this.config.writeQueueWaitTime); + this.writeQueueRef = setTimeout(() => this._runWriteQueue(), this.config.writeQueueWaitTime); } } From 042447d1a81b3f3edf293b18e13fc5f6b76a1fb1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 27 Feb 2021 09:57:29 +0100 Subject: [PATCH 21/22] Stop recreating the dbus.systemBus on retries (old instances are not disposed correctly by underlying code) --- plejd/PlejdAddon.js | 17 +++++++---------- plejd/PlejdBLEHandler.js | 31 +++++++++++++++++++++++++++++-- plejd/PlejdDeviceCommunication.js | 4 +++- 3 files changed, 39 insertions(+), 13 deletions(-) diff --git a/plejd/PlejdAddon.js b/plejd/PlejdAddon.js index 196d986..eb39c50 100644 --- a/plejd/PlejdAddon.js +++ b/plejd/PlejdAddon.js @@ -122,16 +122,13 @@ class PlejdAddon extends EventEmitter { }, ); - this.plejdDeviceCommunication.on( - PlejdDeviceCommunication.EVENTS.sceneTriggered, - (sceneId) => { - try { - this.mqttClient.sceneTriggered(sceneId); - } catch (err) { - logger.error('Error in PlejdService.sceneTriggered callback', err); - } - }, - ); + this.plejdDeviceCommunication.on(PlejdDeviceCommunication.EVENTS.sceneTriggered, (sceneId) => { + try { + this.mqttClient.sceneTriggered(sceneId); + } catch (err) { + logger.error('Error in PlejdService.sceneTriggered callback', err); + } + }); await this.plejdDeviceCommunication.init(); logger.info('Main init done'); diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 05375d8..6f68a76 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -53,6 +53,7 @@ class PlejBLEHandler extends EventEmitter { pingRef = null; requestCurrentPlejdTimeRef = null; reconnectInProgress = false; + emergencyReconnectTimeout = null; // Refer to BLE-states.md regarding the internal BLE/bluez state machine of Bluetooth states // These states refer to the state machine of this file @@ -82,6 +83,8 @@ class PlejBLEHandler extends EventEmitter { auth: null, ping: null, }; + + this.bus = dbus.systemBus(); } cleanup() { @@ -112,7 +115,6 @@ class PlejBLEHandler extends EventEmitter { this.on(PlejBLEHandler.EVENTS.writeFailed, (error) => this._onWriteFailed(error)); this.on(PlejBLEHandler.EVENTS.writeSuccess, () => this._onWriteSuccess()); - this.bus = dbus.systemBus(); this.bus.on('error', (err) => { // Uncaught error events will show UnhandledPromiseRejection logs logger.verbose(`dbus-next error event: ${err.message}`); @@ -290,6 +292,9 @@ class PlejBLEHandler extends EventEmitter { ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); this.emit(PlejBLEHandler.EVENTS.connected); + + clearTimeout(this.emergencyReconnectTimeout); + this.emergencyReconnectTimeout = null; } catch (err) { // This method is run on a timer, so errors can't e re-thrown. // Start reconnect loop if errors occur here @@ -463,10 +468,24 @@ class PlejBLEHandler extends EventEmitter { async startReconnectPeriodicallyLoop() { logger.info('Starting reconnect loop...'); - if (this.reconnectInProgress) { + clearTimeout(this.emergencyReconnectTimeout); + this.emergencyReconnectTimeout = null; + await this._startReconnectPeriodicallyLoopInternal(); + } + + async _startReconnectPeriodicallyLoopInternal() { + logger.verbose('Starting internal reconnect loop...'); + + if (this.reconnectInProgress && !this.emergencyReconnectTimeout) { logger.debug('Reconnect already in progress. Skipping this call.'); return; } + if (this.emergencyReconnectTimeout) { + logger.warn( + 'Restarting reconnect loop due to emergency reconnect timer elapsed. This should very rarely happen!', + ); + } + this.reconnectInProgress = true; /* eslint-disable no-await-in-loop */ @@ -476,6 +495,14 @@ class PlejBLEHandler extends EventEmitter { logger.verbose('Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...'); this.cleanup(); this.emit(PlejBLEHandler.EVENTS.reconnecting); + + // Emergency 2 minute timer if reconnect silently fails somewhere + clearTimeout(this.emergencyReconnectTimeout); + this.emergencyReconnectTimeout = setTimeout( + () => this._startReconnectPeriodicallyLoopInternal(), + 120 * 1000, + ); + await delay(5000); logger.info('Reconnecting BLE...'); await this.init(); diff --git a/plejd/PlejdDeviceCommunication.js b/plejd/PlejdDeviceCommunication.js index 4fafb6c..e64c8cd 100644 --- a/plejd/PlejdDeviceCommunication.js +++ b/plejd/PlejdDeviceCommunication.js @@ -56,7 +56,9 @@ class PlejdDeviceCommunication extends EventEmitter { }); this.plejdBleHandler.on(PlejBLEHandler.EVENTS.reconnecting, () => { logger.info('Bluetooth reconnecting...'); - logger.verbose(`Stopping writeQueue loop until connection is established. Write queue length: ${this.writeQueue.length}`); + logger.verbose( + `Stopping writeQueue loop until connection is established. Write queue length: ${this.writeQueue.length}`, + ); this.bleConnected = false; clearTimeout(this.writeQueueRef); }); From 517ab75e8e3de818985ae06aea6ba0db6804ec04 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Victor=20Hagelb=C3=A4ck?= Date: Sat, 27 Feb 2021 13:46:41 +0100 Subject: [PATCH 22/22] Invoke power cycling of the BLE adapter every 10th reconnect attempt --- plejd/PlejdBLEHandler.js | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/plejd/PlejdBLEHandler.js b/plejd/PlejdBLEHandler.js index 6f68a76..58ea552 100644 --- a/plejd/PlejdBLEHandler.js +++ b/plejd/PlejdBLEHandler.js @@ -48,6 +48,7 @@ class PlejBLEHandler extends EventEmitter { bus = null; connectedDevice = null; consecutiveWriteFails; + consecutiveReconnectAttempts = 0; discoveryTimeout = null; plejdService = null; pingRef = null; @@ -291,6 +292,7 @@ class PlejBLEHandler extends EventEmitter { // invalidated (third param), ) => this._onLastDataUpdated(iface, properties)); this.characteristics.lastData.StartNotify(); + this.consecutiveReconnectAttempts = 0; this.emit(PlejBLEHandler.EVENTS.connected); clearTimeout(this.emergencyReconnectTimeout); @@ -345,18 +347,21 @@ class PlejBLEHandler extends EventEmitter { } async _powerCycleAdapter() { + logger.verbose('Power cycling BLE adapter'); await this._powerOffAdapter(); await this._powerOnAdapter(); } async _powerOnAdapter() { + logger.verbose('Powering on BLE adapter and waiting 5 seconds'); await this.adapterProperties.Set(BLUEZ_ADAPTER_ID, 'Powered', new dbus.Variant('b', 1)); - await delay(1000); + await delay(5000); } async _powerOffAdapter() { + logger.verbose('Powering off BLE adapter and waiting 5 seconds'); await this.adapterProperties.Set(BLUEZ_ADAPTER_ID, 'Powered', new dbus.Variant('b', 0)); - await delay(1000); + await delay(5000); } async _cleanExistingConnections(managedObjects) { @@ -494,6 +499,19 @@ class PlejBLEHandler extends EventEmitter { try { logger.verbose('Reconnect: Clean up, emit reconnect event, wait 5s and the re-init...'); this.cleanup(); + + this.consecutiveReconnectAttempts++; + if (this.consecutiveReconnectAttempts % 10 === 0) { + logger.warn( + `Tried reconnecting ${this.consecutiveReconnectAttempts} times. Try power cycling the BLE adapter every 10th time...`, + ); + await this._powerCycleAdapter(); + } else { + logger.verbose( + `Reconnect attempt ${this.consecutiveReconnectAttempts} in a row. Will power cycle every 10th time.`, + ); + } + this.emit(PlejBLEHandler.EVENTS.reconnecting); // Emergency 2 minute timer if reconnect silently fails somewhere