rasperrypi-home/hassio-plejd
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Improve BLE resilience

Browse source
This commit is contained in:
Victor Hagelbäck 2021-02-08 19:54:24 +01:00
parent 40f79df37e
commit f93d3854d0
2 changed files with 119 additions and 92 deletions
Download patch file Download diff file Expand all files Collapse all files

31
plejd/PlejdAddon.js
View file

@ -99,16 +99,11 @@ class PlejdAddon extends EventEmitter {
this.mqttClient.init(); this.mqttClient.init();
// init the BLE interface this.plejdBLEHandler.on('connected', () => {
this.plejdBLEHandler.on('connectFailed', () => { logger.info('Bluetooth connected. Plejd BLE up and running!');
logger.verbose('Were unable to connect, will retry.');
this._bleInitLoop();
}); });
this.plejdBLEHandler.on('reconnecting', () => {
// this.plejdBLE.init(); logger.info('Bluetooth reconnecting...');
this.plejdBLEHandler.on('authenticated', () => {
logger.verbose('plejd: connected via bluetooth.');
}); });
// subscribe to changes from Plejd // subscribe to changes from Plejd
@ -128,25 +123,13 @@ class PlejdAddon extends EventEmitter {
} }
}); });
await this._bleInitLoop();
}
async _bleInitLoop() {
try { try {
if (this.bleInitTimeout) {
clearTimeout(this.bleInitTimeout);
}
await this.plejdBLEHandler.init(); await this.plejdBLEHandler.init();
} catch (err) { } catch (err) {
logger.warn('Failed BLE init, trying again in 35s', err); logger.error('Failed init() of BLE. Starting reconnect loop.');
this.bleInitTimer = setTimeout(() => { await this.plejdBLEHandler.startReconnectPeriodicallyLoop();
try {
this._bleInitLoop();
} catch (err2) {
logger.warn('Why do we need to catch error here?', err2);
}
}, 35000);
} }
logger.info('Main init done');
} }
} }

180
plejd/PlejdBLEHandler.js
View file

@ -40,11 +40,14 @@ class PlejBLEHandler extends EventEmitter {
adapterProperties; adapterProperties;
config; config;
deviceRegistry; deviceRegistry;
consecutiveWriteFails;
// Refer to BLE-states.md regarding the internal BLE/bluez state machine of Bluetooth states // 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 // These states refer to the state machine of this file
static STATES = ['MAIN_INIT', 'GET_ADAPTER_PROXY']; static STATES = ['MAIN_INIT', 'GET_ADAPTER_PROXY'];
static EVENTS = ['connected', 'reconnecting', 'sceneTriggered', 'stateChanged'];
constructor(deviceRegistry) { constructor(deviceRegistry) {
super(); super();
@ -62,7 +65,7 @@ class PlejBLEHandler extends EventEmitter {
this.connectEventHooked = false; this.connectEventHooked = false;
this.writeQueue = []; this.writeQueue = [];
this.writeQueueRef = null; this.writeQueueRef = null;
this.initInProgress = null; this.reconnectInProgress = false;
// Holds a reference to all characteristics // Holds a reference to all characteristics
this.characteristics = { this.characteristics = {
@ -74,6 +77,9 @@ class PlejBLEHandler extends EventEmitter {
}; };
this.bus = null; this.bus = null;
this.on('writeFailed', (error) => this.onWriteFailed(error));
this.on('writeSuccess', () => this.onWriteSuccess());
} }
async init() { async init() {
@ -81,6 +87,7 @@ class PlejBLEHandler extends EventEmitter {
this.bus = dbus.systemBus(); this.bus = dbus.systemBus();
this.adapter = null; this.adapter = null;
this.adapterProperties = null; this.adapterProperties = null;
this.consecutiveWriteFails = 0;
this.cryptoKey = Buffer.from(this.deviceRegistry.cryptoKey.replace(/-/g, ''), 'hex'); this.cryptoKey = Buffer.from(this.deviceRegistry.cryptoKey.replace(/-/g, ''), 'hex');
@ -102,7 +109,7 @@ class PlejBLEHandler extends EventEmitter {
await this._getInterface(); await this._getInterface();
await this._startGetPlejdDevice(); await this._startGetPlejdDevice();
logger.info('Init done'); logger.info('BLE init done, waiting for devices.');
} }
async _initDiscoveredPlejdDevice(path) { async _initDiscoveredPlejdDevice(path) {
@ -135,8 +142,9 @@ class PlejBLEHandler extends EventEmitter {
async _inspectDevicesDiscovered() { async _inspectDevicesDiscovered() {
if (this.bleDevices.length === 0) { if (this.bleDevices.length === 0) {
logger.error('Discovery timeout elapsed, no devices found. Exiting...'); logger.error('Discovery timeout elapsed, no devices found. Starting reconnect loop...');
throw new Error('Discovery timeout elapsed, no devices found'); this.startReconnectPeriodicallyLoop();
return;
} }
logger.info(`Device discovery done, found ${this.bleDevices.length} Plejd devices`); logger.info(`Device discovery done, found ${this.bleDevices.length} Plejd devices`);
@ -146,7 +154,7 @@ class PlejBLEHandler extends EventEmitter {
// eslint-disable-next-line no-restricted-syntax // eslint-disable-next-line no-restricted-syntax
for (const plejd of sortedDevices) { for (const plejd of sortedDevices) {
try { try {
console.log('Inspecting', plejd); logger.verbose(`Inspecting ${plejd.path}`);
if (plejd.instance) { if (plejd.instance) {
logger.info(`Connecting to ${plejd.path}`); logger.info(`Connecting to ${plejd.path}`);
// eslint-disable-next-line no-await-in-loop // eslint-disable-next-line no-await-in-loop
@ -184,20 +192,24 @@ class PlejBLEHandler extends EventEmitter {
logger.verbose('Trying again...'); logger.verbose('Trying again...');
await this._startGetPlejdDevice(); await this._startGetPlejdDevice();
} catch (errInner) { } catch (errInner) {
throw new Error('Failed to retry internalInit.'); logger.error('Failed to retry internalInit. Starting reconnect loop');
this.startReconnectPeriodicallyLoop();
return;
} }
} }
throw new Error( logger.error('Failed to start discovery. Make sure no other add-on is currently scanning.');
'Failed to start discovery. Make sure no other add-on is currently scanning.', return;
);
} }
if (!this.connectedDevice) { if (!this.connectedDevice) {
logger.error('Could not connect to any Plejd device. Exiting...'); logger.error('Could not connect to any Plejd device. Starting reconnect loop...');
this.emit('connectFailed'); this.startReconnectPeriodicallyLoop();
throw new Error('Could not connect to any Plejd device'); return;
} }
logger.info(`BLE Connected to ${this.connectedDevice.name}`);
this.emit('connected');
// Connected and authenticated, start ping // Connected and authenticated, start ping
this.startPing(); this.startPing();
this.startWriteQueue(); this.startWriteQueue();
@ -220,8 +232,7 @@ class PlejBLEHandler extends EventEmitter {
const managedObjects = await this.objectManager.GetManagedObjects(); const managedObjects = await this.objectManager.GetManagedObjects();
const managedPaths = Object.keys(managedObjects); const managedPaths = Object.keys(managedObjects);
console.log('Managed objects', managedObjects); logger.verbose(`Managed paths${JSON.stringify(managedPaths, null, 2)}`);
console.log('Managed paths', managedPaths);
// eslint-disable-next-line no-restricted-syntax // eslint-disable-next-line no-restricted-syntax
for (const path of managedPaths) { for (const path of managedPaths) {
@ -231,7 +242,6 @@ class PlejBLEHandler extends EventEmitter {
try { try {
// eslint-disable-next-line no-await-in-loop // eslint-disable-next-line no-await-in-loop
const adapterObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path); const adapterObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path);
console.log('Got adapter results', adapterObject);
// eslint-disable-next-line no-await-in-loop // eslint-disable-next-line no-await-in-loop
this.adapterProperties = await adapterObject.getInterface(DBUS_PROP_INTERFACE); this.adapterProperties = await adapterObject.getInterface(DBUS_PROP_INTERFACE);
// eslint-disable-next-line no-await-in-loop // eslint-disable-next-line no-await-in-loop
@ -239,6 +249,9 @@ class PlejBLEHandler extends EventEmitter {
this.adapter = adapterObject.getInterface(BLUEZ_ADAPTER_ID); this.adapter = adapterObject.getInterface(BLUEZ_ADAPTER_ID);
// eslint-disable-next-line no-await-in-loop // eslint-disable-next-line no-await-in-loop
await this._cleanExistingConnections(managedObjects); await this._cleanExistingConnections(managedObjects);
logger.verbose(`Got adapter ${this.adapter.path}`);
return this.adapter; return this.adapter;
} catch (err) { } catch (err) {
logger.error(`Failed to get interface '${BLUEZ_ADAPTER_ID}'. `, err); logger.error(`Failed to get interface '${BLUEZ_ADAPTER_ID}'. `, err);
@ -283,7 +296,7 @@ class PlejBLEHandler extends EventEmitter {
const proxyObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path); const proxyObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path);
const device = await proxyObject.getInterface(BLUEZ_DEVICE_ID); const device = await proxyObject.getInterface(BLUEZ_DEVICE_ID);
logger.verbose(`Found ${path} - ${JSON.stringify(device.device)}`); logger.verbose(`Found ${path}`);
const connected = managedObjects[path][BLUEZ_DEVICE_ID].Connected.value; const connected = managedObjects[path][BLUEZ_DEVICE_ID].Connected.value;
@ -306,9 +319,7 @@ class PlejBLEHandler extends EventEmitter {
async _startGetPlejdDevice() { async _startGetPlejdDevice() {
logger.verbose('Setting up interfacesAdded subscription and discovery filter'); logger.verbose('Setting up interfacesAdded subscription and discovery filter');
this.objectManager.on('InterfacesAdded', (path, interfaces) => this.objectManager.on('InterfacesAdded', (path, interfaces) => this.onInterfacesAdded(path, interfaces));
this.onInterfacesAdded(path, interfaces),
);
this.adapter.SetDiscoveryFilter({ this.adapter.SetDiscoveryFilter({
UUIDs: new dbus.Variant('as', [PLEJD_SERVICE]), UUIDs: new dbus.Variant('as', [PLEJD_SERVICE]),
@ -391,11 +402,11 @@ class PlejBLEHandler extends EventEmitter {
const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable; const isDimmable = this.deviceRegistry.getDevice(deviceId).dimmable;
if ( if (
transition > 1 && transition > 1
isDimmable && && isDimmable
(initialBrightness || initialBrightness === 0) && && (initialBrightness || initialBrightness === 0)
(targetBrightness || targetBrightness === 0) && && (targetBrightness || targetBrightness === 0)
targetBrightness !== initialBrightness && targetBrightness !== initialBrightness
) { ) {
// Transition time set, known initial and target brightness // Transition time set, known initial and target brightness
// Calculate transition interval time based on delta brightness and max steps per second // Calculate transition interval time based on delta brightness and max steps per second
@ -519,24 +530,33 @@ class PlejBLEHandler extends EventEmitter {
} }
} }
async throttledInit(delayMs) { async startReconnectPeriodicallyLoop() {
if (this.initInProgress) { if (this.reconnectInProgress) {
logger.debug( logger.debug(
'ThrottledInit already in progress. Skipping this call and returning existing promise.', 'Reconnect already in progress. Skipping this call and returning existing promise.',
); );
return this.initInProgress; return;
} }
this.initInProgress = new Promise((resolve) => clearInterval(this.pingRef);
setTimeout(async () => { clearTimeout(this.writeQueueRef);
const result = await this.init().catch((err) => { this.reconnectInProgress = true;
logger.error('TrottledInit exception calling init(). Will re-throw.', err);
throw err; /* eslint-disable no-await-in-loop */
}); // eslint-disable-next-line no-constant-condition
this.initInProgress = null; while (true) {
resolve(result); try {
}, delayMs), this.emit('reconnecting');
); logger.info('Reconnecting BLE...');
return this.initInProgress; await this.init();
break;
} catch (err) {
logger.warn('Failed reconnecting', err);
await delay(1000);
}
}
/* eslint-enable no-await-in-loop */
this.reconnectInProgress = false;
} }
async write(data) { async write(data) {
@ -549,6 +569,7 @@ class PlejBLEHandler extends EventEmitter {
logger.verbose(`Sending ${data.length} byte(s) of data to Plejd. ${data.toString('hex')}`); logger.verbose(`Sending ${data.length} byte(s) of data to Plejd. ${data.toString('hex')}`);
const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data); const encryptedData = this._encryptDecrypt(this.cryptoKey, this.plejdService.addr, data);
await this.characteristics.data.WriteValue([...encryptedData], {}); await this.characteristics.data.WriteValue([...encryptedData], {});
await this.onWriteSuccess();
return true; return true;
} catch (err) { } catch (err) {
if (err.message === 'In Progress') { if (err.message === 'In Progress') {
@ -556,7 +577,7 @@ class PlejBLEHandler extends EventEmitter {
} else { } else {
logger.debug('Write failed ', err); logger.debug('Write failed ', err);
} }
await this.throttledInit(this.config.connectionTimeout * 1000); await this.onWriteFailed(err);
return false; return false;
} }
} }
@ -572,18 +593,36 @@ class PlejBLEHandler extends EventEmitter {
} }
// eslint-disable-next-line class-methods-use-this // eslint-disable-next-line class-methods-use-this
onPingSuccess(nr) { onWriteSuccess() {
logger.silly(`pong: ${nr}`); this.consecutiveWriteFails = 0;
} }
async onPingFailed(error) { async onWriteFailed(error) {
logger.debug(`onPingFailed(${error})`); this.consecutiveWriteFails++;
logger.info('ping failed, reconnecting.'); logger.debug(`onWriteFailed #${this.consecutiveWriteFails} in a row.`, error);
clearInterval(this.pingRef); let errorIndicatesDisconnected = false;
return this.init().catch((err) => { if (error.message.contains('error: 0x0e')) {
logger.error('onPingFailed exception calling init(). Will swallow error.', err); logger.error("'Unlikely error' (0x0e) pinging Plejd. Will retry.", error);
}); } else if (error.message.contains('Not connected')) {
logger.error("'Not connected' (0x0e) pinging Plejd. Plejd device is probably disconnected.");
errorIndicatesDisconnected = true;
} else if (
error.message.contains(
'Method "WriteValue" with signature "aya{sv}" on interface "org.bluez.GattCharacteristic1" doesn\'t exist',
)
) {
logger.error("'Method \"WriteValue\" doesn't exist'. Plejd device is probably disconnected.");
errorIndicatesDisconnected = true;
}
if (errorIndicatesDisconnected) {
logger.warn('Write error indicates BLE is disconnected. Reconnecting...');
await this.startReconnectPeriodicallyLoop();
} else if (this.consecutiveWriteFails >= 5) {
logger.warn('Write failed 5 times in a row, reconnecting....');
await this.startReconnectPeriodicallyLoop();
}
} }
async ping() { async ping() {
@ -596,19 +635,20 @@ class PlejBLEHandler extends EventEmitter {
await this.characteristics.ping.WriteValue([...ping], {}); await this.characteristics.ping.WriteValue([...ping], {});
pong = await this.characteristics.ping.ReadValue({}); pong = await this.characteristics.ping.ReadValue({});
} catch (err) { } catch (err) {
logger.error('Error writing to plejd: ', err); logger.error(`Error pinging Plejd ${err.message}`);
this.emit('pingFailed', 'write error'); await this.onWriteFailed(err);
return; return;
} }
// eslint-disable-next-line no-bitwise // eslint-disable-next-line no-bitwise
if (((ping[0] + 1) & 0xff) !== pong[0]) { if (((ping[0] + 1) & 0xff) !== pong[0]) {
logger.error('Plejd ping failed'); logger.error('Plejd ping failed');
this.emit('pingFailed', `plejd ping failed ${ping[0]} - ${pong[0]}`); await this.onWriteFailed(new Error(`plejd ping failed ${ping[0]} - ${pong[0]}`));
return; return;
} }
this.emit('pingSuccess', pong[0]); logger.silly(`pong: ${pong[0]}`);
await this.onWriteSuccess();
} }
startWriteQueue() { startWriteQueue() {
@ -629,8 +669,8 @@ class PlejBLEHandler extends EventEmitter {
if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) { if (this.writeQueue.some((item) => item.deviceId === queueItem.deviceId)) {
logger.verbose( logger.verbose(
`Skipping ${deviceName} (${queueItem.deviceId}) ` + `Skipping ${deviceName} (${queueItem.deviceId}) `
`${queueItem.log} due to more recent command in queue.`, + `${queueItem.log} due to more recent command in queue.`,
); );
// Skip commands if new ones exist for the same deviceId // Skip commands if new ones exist for the same deviceId
// still process all messages in order // still process all messages in order
@ -691,17 +731,17 @@ class PlejBLEHandler extends EventEmitter {
const chUuid = (await prop.Get(GATT_CHRC_ID, 'UUID')).value; const chUuid = (await prop.Get(GATT_CHRC_ID, 'UUID')).value;
if (chUuid === DATA_UUID) { if (chUuid === DATA_UUID) {
logger.debug('found DATA characteristic.'); logger.verbose('found DATA characteristic.');
this.characteristics.data = ch; this.characteristics.data = ch;
} else if (chUuid === LAST_DATA_UUID) { } else if (chUuid === LAST_DATA_UUID) {
logger.debug('found LAST_DATA characteristic.'); logger.verbose('found LAST_DATA characteristic.');
this.characteristics.lastData = ch; this.characteristics.lastData = ch;
this.characteristics.lastDataProperties = prop; this.characteristics.lastDataProperties = prop;
} else if (chUuid === AUTH_UUID) { } else if (chUuid === AUTH_UUID) {
logger.debug('found AUTH characteristic.'); logger.verbose('found AUTH characteristic.');
this.characteristics.auth = ch; this.characteristics.auth = ch;
} else if (chUuid === PING_UUID) { } else if (chUuid === PING_UUID) {
logger.debug('found PING characteristic.'); logger.verbose('found PING characteristic.');
this.characteristics.ping = ch; this.characteristics.ping = ch;
} }
/* eslint-eslint no-await-in-loop */ /* eslint-eslint no-await-in-loop */
@ -715,23 +755,23 @@ class PlejBLEHandler extends EventEmitter {
async _onDeviceConnected(device) { async _onDeviceConnected(device) {
this.connectedDevice = null; this.connectedDevice = null;
logger.info('onDeviceConnected()'); logger.info('onDeviceConnected()');
logger.debug(`Device: ${JSON.stringify(device.device)}`); logger.debug(`Device ${device.path}, ${JSON.stringify(device.device)}`);
const objects = await this.objectManager.GetManagedObjects(); const objects = await this.objectManager.GetManagedObjects();
const paths = Object.keys(objects); const paths = Object.keys(objects);
const characteristics = []; const characteristics = [];
console.log(`Iterating looking for ${GATT_CHRC_ID}`, paths); logger.verbose(`Iterating connected devices looking for ${GATT_CHRC_ID}`);
// eslint-disable-next-line no-restricted-syntax // eslint-disable-next-line no-restricted-syntax
for (const path of paths) { for (const path of paths) {
const interfaces = Object.keys(objects[path]); const interfaces = Object.keys(objects[path]);
console.log('Interfaces', path, interfaces); logger.verbose(`Interfaces ${path}: ${JSON.stringify(interfaces)}`);
if (interfaces.indexOf(GATT_CHRC_ID) > -1) { if (interfaces.indexOf(GATT_CHRC_ID) > -1) {
characteristics.push(path); characteristics.push(path);
} }
} }
console.log('Characteristics', characteristics); logger.verbose(`Characteristics found: ${JSON.stringify(characteristics)}`);
// eslint-disable-next-line no-restricted-syntax // eslint-disable-next-line no-restricted-syntax
for (const path of paths) { for (const path of paths) {
const interfaces = Object.keys(objects[path]); const interfaces = Object.keys(objects[path]);
@ -744,7 +784,7 @@ class PlejBLEHandler extends EventEmitter {
} }
} }
logger.info(`trying ${chPaths.length} characteristics`); logger.verbose(`Trying ${chPaths.length} characteristics on ${path}...`);
this.plejdService = await this._processPlejdService(path, chPaths); this.plejdService = await this._processPlejdService(path, chPaths);
if (this.plejdService) { if (this.plejdService) {
@ -763,6 +803,8 @@ class PlejBLEHandler extends EventEmitter {
return null; return null;
} }
logger.info('Connected device is a Plejd device with the right characteristics.');
this.connectedDevice = device.device; this.connectedDevice = device.device;
await this.authenticate(); await this.authenticate();
@ -791,7 +833,7 @@ class PlejBLEHandler extends EventEmitter {
if (decoded.length < 5) { if (decoded.length < 5) {
if (Logger.shouldLog('debug')) { if (Logger.shouldLog('debug')) {
// decoded.toString() could potentially be expensive // decoded.toString() could potentially be expensive
logger.debug(`Too short raw event ignored: ${decoded.toString('hex')}`); logger.verbose(`Too short raw event ignored: ${decoded.toString('hex')}`);
} }
// ignore the notification since too small // ignore the notification since too small
return; return;
@ -808,8 +850,10 @@ class PlejBLEHandler extends EventEmitter {
const deviceName = this.deviceRegistry.getDeviceName(deviceId); const deviceName = this.deviceRegistry.getDeviceName(deviceId);
if (Logger.shouldLog('debug')) { if (Logger.shouldLog('debug')) {
// decoded.toString() could potentially be expensive // decoded.toString() could potentially be expensive
logger.debug(`Raw event received: ${decoded.toString('hex')}`); logger.verbose(`Raw event received: ${decoded.toString('hex')}`);
logger.verbose(`Device ${deviceId}, cmd ${cmd.toString(16)}, state ${state}, dim ${dim}`); logger.verbose(
`Decoded: Device ${deviceId}, cmd ${cmd.toString(16)}, state ${state}, dim ${dim}`,
);
} }
if (cmd === BLE_CMD_DIM_CHANGE || cmd === BLE_CMD_DIM2_CHANGE) { if (cmd === BLE_CMD_DIM_CHANGE || cmd === BLE_CMD_DIM2_CHANGE) {
@ -824,7 +868,7 @@ class PlejBLEHandler extends EventEmitter {
state, state,
dim, dim,
}; };
logger.verbose(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`); logger.silly(`All states: ${JSON.stringify(this.plejdDevices, null, 2)}`);
} else if (cmd === BLE_CMD_STATE_CHANGE) { } else if (cmd === BLE_CMD_STATE_CHANGE) {
logger.debug(`${deviceName} (${deviceId}) got state update. S: ${state}`); logger.debug(`${deviceName} (${deviceId}) got state update. S: ${state}`);
this.emit('stateChanged', deviceId, { this.emit('stateChanged', deviceId, {