First async/await rewrite of PlejdBLE

This commit is contained in:
Victor Hagelbäck 2021-02-08 07:38:31 +01:00
parent 898a9d822f
commit 7436c56c25

View file

@ -9,11 +9,12 @@ const Configuration = require('./Configuration');
const logger = Logger.getLogger('plejd-ble'); const logger = Logger.getLogger('plejd-ble');
// UUIDs // UUIDs
const PLEJD_SERVICE = '31ba0001-6085-4726-be45-040c957391b5'; const BLE_UUID_SUFFIX = '6085-4726-be45-040c957391b5';
const DATA_UUID = '31ba0004-6085-4726-be45-040c957391b5'; const PLEJD_SERVICE = `31ba0001-${BLE_UUID_SUFFIX}`;
const LAST_DATA_UUID = '31ba0005-6085-4726-be45-040c957391b5'; const DATA_UUID = `31ba0004-${BLE_UUID_SUFFIX}`;
const AUTH_UUID = '31ba0009-6085-4726-be45-040c957391b5'; const LAST_DATA_UUID = `31ba0005-${BLE_UUID_SUFFIX}`;
const PING_UUID = '31ba000a-6085-4726-be45-040c957391b5'; const AUTH_UUID = `31ba0009-${BLE_UUID_SUFFIX}`;
const PING_UUID = `31ba000a-${BLE_UUID_SUFFIX}`;
const BLE_CMD_DIM_CHANGE = 0xc8; const BLE_CMD_DIM_CHANGE = 0xc8;
const BLE_CMD_DIM2_CHANGE = 0x98; const BLE_CMD_DIM2_CHANGE = 0x98;
@ -34,22 +35,29 @@ const MAX_RETRY_COUNT = 5; // Could be made a setting
const delay = (timeout) => new Promise((resolve) => setTimeout(resolve, timeout)); const delay = (timeout) => new Promise((resolve) => setTimeout(resolve, timeout));
class PlejBLE extends EventEmitter { class PlejBLEHandler extends EventEmitter {
adapter;
adapterProperties;
config; config;
deviceRegistry; deviceRegistry;
// 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'];
constructor(deviceRegistry) { constructor(deviceRegistry) {
super(); super();
logger.info('Starting Plejd BLE, resetting all device states.'); logger.info('Starting Plejd BLE Handler, resetting all device states.');
this.config = Configuration.getOptions(); this.config = Configuration.getOptions();
this.deviceRegistry = deviceRegistry;
this.connectedDevice = null; this.connectedDevice = null;
this.deviceRegistry = deviceRegistry;
this.plejdService = null; this.plejdService = null;
this.bleDevices = []; this.bleDevices = [];
this.bleDeviceTransitionTimers = {}; this.bleDeviceTransitionTimers = {};
this.discoveryTimeout = null;
this.plejdDevices = {}; this.plejdDevices = {};
this.connectEventHooked = false; this.connectEventHooked = false;
this.writeQueue = []; this.writeQueue = [];
@ -66,15 +74,13 @@ class PlejBLE extends EventEmitter {
}; };
this.bus = null; this.bus = null;
this.adapter = null;
} }
async init() { async init() {
logger.info('init()'); logger.info('init()');
this.bus = dbus.systemBus(); this.bus = dbus.systemBus();
this.adapter = null;
logger.debug('wiring events and waiting for BLE interface to power up.'); this.adapterProperties = null;
this.wireEvents();
this.cryptoKey = Buffer.from(this.deviceRegistry.cryptoKey.replace(/-/g, ''), 'hex'); this.cryptoKey = Buffer.from(this.deviceRegistry.cryptoKey.replace(/-/g, ''), 'hex');
@ -93,25 +99,174 @@ class PlejBLE extends EventEmitter {
ping: null, ping: null,
}; };
clearInterval(this.pingRef); await this._getInterface();
clearTimeout(this.writeQueueRef); await this._startGetPlejdDevice();
logger.info('Init done');
}
async _initDiscoveredPlejdDevice(path) {
logger.debug(`initDiscoveredPlejdDevice(). Got ${path} device`);
logger.debug(`Inspecting ${path}`);
try {
const proxyObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path);
const device = await proxyObject.getInterface(BLUEZ_DEVICE_ID);
const properties = await proxyObject.getInterface(DBUS_PROP_INTERFACE);
const plejd = { path };
plejd.rssi = (await properties.Get(BLUEZ_DEVICE_ID, 'RSSI')).value;
plejd.instance = device;
const segments = plejd.path.split('/');
let fixedPlejdPath = segments[segments.length - 1].replace('dev_', '');
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);
} catch (err) {
logger.error(`Failed inspecting ${path}. `, err);
}
}
async _inspectDevicesDiscovered() {
if (this.bleDevices.length === 0) {
logger.error('Discovery timeout elapsed, no devices found. Exiting...');
throw new Error('Discovery timeout elapsed, no devices found');
}
logger.info(`Device discovery done, found ${this.bleDevices.length} Plejd devices`);
const sortedDevices = this.bleDevices.sort((a, b) => b.rssi - a.rssi);
// eslint-disable-next-line no-restricted-syntax
for (const plejd of sortedDevices) {
try {
console.log('Inspecting', plejd);
if (plejd.instance) {
logger.info(`Connecting to ${plejd.path}`);
// eslint-disable-next-line no-await-in-loop
await plejd.instance.Connect();
logger.verbose('Connected. Waiting for timeout before reading characteristics...');
// eslint-disable-next-line no-await-in-loop
await delay(this.config.connectionTimeout * 1000);
// eslint-disable-next-line no-await-in-loop
const connectedPlejdDevice = await this._onDeviceConnected(plejd);
if (connectedPlejdDevice) {
break;
}
}
} catch (err) {
logger.warn('Unable to connect.', err);
}
}
try {
logger.verbose('Stopping discovery...');
await this.adapter.StopDiscovery();
logger.verbose('Stopped BLE discovery');
} catch (err) {
logger.error('Failed to stop discovery.', err);
if (err.message.includes('Operation already in progress')) {
logger.info(
'If you continue to get "operation already in progress" error, you can try power cycling the bluetooth adapter. Get root console access, run "bluetoothctl" => "power off" => "power on" => "exit" => restart addon.',
);
try {
await delay(250);
logger.verbose('Power cycling...');
await this._powerCycleAdapter();
logger.verbose('Trying again...');
await this._startGetPlejdDevice();
} catch (errInner) {
throw new Error('Failed to retry internalInit.');
}
}
throw new Error(
'Failed to start discovery. Make sure no other add-on is currently scanning.',
);
}
if (!this.connectedDevice) {
logger.error('Could not connect to any Plejd device. Exiting...');
this.emit('connectFailed');
throw new Error('Could not connect to any Plejd device');
}
// Connected and authenticated, start ping
this.startPing();
this.startWriteQueue();
// After we've authenticated, we need to hook up the event listener
// for changes to lastData.
this.characteristics.lastDataProperties.on('PropertiesChanged', (
iface,
properties,
// invalidated (third param),
) => this.onLastDataUpdated(iface, properties));
this.characteristics.lastData.StartNotify();
}
async _getInterface() {
const bluez = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, '/'); const bluez = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, '/');
this.objectManager = await bluez.getInterface(DBUS_OM_INTERFACE); this.objectManager = await bluez.getInterface(DBUS_OM_INTERFACE);
// We need to find the ble interface which implements the Adapter1 interface // We need to find the ble interface which implements the Adapter1 interface
const managedObjects = await this.objectManager.GetManagedObjects(); const managedObjects = await this.objectManager.GetManagedObjects();
const result = await this._getInterface(managedObjects, BLUEZ_ADAPTER_ID); const managedPaths = Object.keys(managedObjects);
if (result) { console.log('Managed objects', managedObjects);
this.adapter = result[1]; console.log('Managed paths', managedPaths);
// eslint-disable-next-line no-restricted-syntax
for (const path of managedPaths) {
const pathInterfaces = Object.keys(managedObjects[path]);
if (pathInterfaces.indexOf(BLUEZ_ADAPTER_ID) > -1) {
logger.debug(`Found BLE interface '${BLUEZ_ADAPTER_ID}' at ${path}`);
try {
// eslint-disable-next-line no-await-in-loop
const adapterObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path);
console.log('Got adapter results', adapterObject);
// eslint-disable-next-line no-await-in-loop
this.adapterProperties = await adapterObject.getInterface(DBUS_PROP_INTERFACE);
// eslint-disable-next-line no-await-in-loop
await this._powerOnAdapter();
this.adapter = adapterObject.getInterface(BLUEZ_ADAPTER_ID);
// eslint-disable-next-line no-await-in-loop
await this._cleanExistingConnections(managedObjects);
return this.adapter;
} catch (err) {
logger.error(`Failed to get interface '${BLUEZ_ADAPTER_ID}'. `, err);
}
}
} }
if (!this.adapter) { this.adapter = null;
logger.error('Unable to find a bluetooth adapter that is compatible.'); logger.error('Unable to find a bluetooth adapter that is compatible.');
throw new Error('Unable to find a bluetooth adapter that is compatible.'); throw new Error('Unable to find a bluetooth adapter that is compatible.');
} }
async _powerCycleAdapter() {
await this._powerOffAdapter();
await this._powerOnAdapter();
}
async _powerOnAdapter() {
await this.adapterProperties.Set(BLUEZ_ADAPTER_ID, 'Powered', new dbus.Variant('b', 1));
await delay(1000);
}
async _powerOffAdapter() {
await this.adapterProperties.Set(BLUEZ_ADAPTER_ID, 'Powered', new dbus.Variant('b', 0));
await delay(1000);
}
async _cleanExistingConnections(managedObjects) {
logger.verbose( logger.verbose(
`Iterating ${ `Iterating ${
Object.keys(managedObjects).length Object.keys(managedObjects).length
@ -147,9 +302,13 @@ class PlejBLE extends EventEmitter {
} }
logger.verbose('All active BLE device connections cleaned up.'); logger.verbose('All active BLE device connections cleaned up.');
}
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.onInterfacesAdded(path, interfaces)); this.objectManager.on('InterfacesAdded', (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]),
@ -158,6 +317,7 @@ class PlejBLE extends EventEmitter {
try { try {
logger.verbose('Starting BLE discovery... This can take up to 180 seconds.'); logger.verbose('Starting BLE discovery... This can take up to 180 seconds.');
this._scheduleInternalInit();
await this.adapter.StartDiscovery(); await this.adapter.StartDiscovery();
logger.verbose('Started BLE discovery'); logger.verbose('Started BLE discovery');
} catch (err) { } catch (err) {
@ -171,90 +331,11 @@ class PlejBLE extends EventEmitter {
'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.',
); );
} }
await delay(this.config.connectionTimeout * 1000);
await this._internalInit();
logger.info('Init done');
} }
async _internalInit() { _scheduleInternalInit() {
logger.debug(`InternalInit(). Got ${this.bleDevices.length} device(s).`); clearTimeout(this.discoveryTimeout);
if (this.bleDevices.length === 0) { setTimeout(() => this._inspectDevicesDiscovered(), this.config.connectionTimeout * 1000);
logger.warn('No devices, init will presumably not work');
}
// eslint-disable-next-line no-restricted-syntax
for (const plejd of this.bleDevices) {
/* eslint-disable no-await-in-loop */
logger.debug(`Inspecting ${plejd.path}`);
try {
const proxyObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, plejd.path);
const device = await proxyObject.getInterface(BLUEZ_DEVICE_ID);
const properties = await proxyObject.getInterface(DBUS_PROP_INTERFACE);
plejd.rssi = (await properties.Get(BLUEZ_DEVICE_ID, 'RSSI')).value;
plejd.instance = device;
const segments = plejd.path.split('/');
let fixedPlejdPath = segments[segments.length - 1].replace('dev_', '');
fixedPlejdPath = fixedPlejdPath.replace(/_/g, '');
plejd.device = this.deviceRegistry.getDeviceBySerialNumber(fixedPlejdPath);
logger.debug(`Discovered ${plejd.path} with rssi ${plejd.rssi}`);
} catch (err) {
logger.error(`Failed inspecting ${plejd.path}. `, err);
}
/* eslint-enable no-await-in-loop */
}
const sortedDevices = this.bleDevices.sort((a, b) => b.rssi - a.rssi);
let connectedDevice = null;
// eslint-disable-next-line no-restricted-syntax
for (const plejd of sortedDevices) {
try {
if (plejd.instance) {
logger.info(`Connecting to ${plejd.path}`);
// eslint-disable-next-line no-await-in-loop
await plejd.instance.Connect();
connectedDevice = plejd;
break;
}
} catch (err) {
logger.error('Warning: unable to connect, will retry. ', err);
}
}
await delay(this.config.connectionTimeout * 1000);
await this.onDeviceConnected(connectedDevice);
logger.verbose('Stopping discovery...');
await this.adapter.StopDiscovery();
}
async _getInterface(managedObjects, iface) {
const managedPaths = Object.keys(managedObjects);
// eslint-disable-next-line no-restricted-syntax
for (const path of managedPaths) {
const pathInterfaces = Object.keys(managedObjects[path]);
if (pathInterfaces.indexOf(iface) > -1) {
logger.debug(`Found BLE interface '${iface}' at ${path}`);
try {
// eslint-disable-next-line no-await-in-loop
const adapterObject = await this.bus.getProxyObject(BLUEZ_SERVICE_NAME, path);
return [path, adapterObject.getInterface(iface), adapterObject];
} catch (err) {
logger.error(`Failed to get interface '${iface}'. `, err);
}
}
}
return null;
} }
async onInterfacesAdded(path, interfaces) { async onInterfacesAdded(path, interfaces) {
@ -265,9 +346,8 @@ class PlejBLE extends EventEmitter {
if (interfaceKeys.indexOf(BLUEZ_DEVICE_ID) > -1) { if (interfaceKeys.indexOf(BLUEZ_DEVICE_ID) > -1) {
if (interfaces[BLUEZ_DEVICE_ID].UUIDs.value.indexOf(PLEJD_SERVICE) > -1) { if (interfaces[BLUEZ_DEVICE_ID].UUIDs.value.indexOf(PLEJD_SERVICE) > -1) {
logger.debug(`Found Plejd service on ${path}`); logger.debug(`Found Plejd service on ${path}`);
this.bleDevices.push({
path, await this._initDiscoveredPlejdDevice(path);
});
} else { } else {
logger.error('Uh oh, no Plejd device!'); logger.error('Uh oh, no Plejd device!');
} }
@ -311,11 +391,11 @@ class PlejBLE 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
@ -435,19 +515,8 @@ class PlejBLE extends EventEmitter {
await this.characteristics.auth.WriteValue([...response], {}); await this.characteristics.auth.WriteValue([...response], {});
} catch (err) { } catch (err) {
logger.error('Failed to authenticate: ', err); logger.error('Failed to authenticate: ', err);
throw new Error('Failed to authenticate');
} }
// auth done, start ping
this.startPing();
this.startWriteQueue();
// After we've authenticated, we need to hook up the event listener
// for changes to lastData.
this.characteristics.lastDataProperties.on(
'PropertiesChanged',
this.onLastDataUpdated.bind(this),
);
this.characteristics.lastData.StartNotify();
} }
async throttledInit(delayMs) { async throttledInit(delayMs) {
@ -457,14 +526,16 @@ class PlejBLE extends EventEmitter {
); );
return this.initInProgress; return this.initInProgress;
} }
this.initInProgress = new Promise((resolve) => setTimeout(async () => { this.initInProgress = new Promise((resolve) =>
const result = await this.init().catch((err) => { setTimeout(async () => {
logger.error('TrottledInit exception calling init(). Will re-throw.', err); const result = await this.init().catch((err) => {
throw err; logger.error('TrottledInit exception calling init(). Will re-throw.', err);
}); throw err;
this.initInProgress = null; });
resolve(result); this.initInProgress = null;
}, delayMs)); resolve(result);
}, delayMs),
);
return this.initInProgress; return this.initInProgress;
} }
@ -558,8 +629,8 @@ class PlejBLE 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
@ -641,26 +712,26 @@ class PlejBLE extends EventEmitter {
}; };
} }
async onDeviceConnected(device) { async _onDeviceConnected(device) {
this.connectedDevice = null;
logger.info('onDeviceConnected()'); logger.info('onDeviceConnected()');
logger.debug(`Device: ${JSON.stringify(device.device)}`); logger.debug(`Device: ${JSON.stringify(device.device)}`);
if (!device) {
logger.error('onDeviceConnected device is null. Returning.');
return;
}
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);
// 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);
if (interfaces.indexOf(GATT_CHRC_ID) > -1) { if (interfaces.indexOf(GATT_CHRC_ID) > -1) {
characteristics.push(path); characteristics.push(path);
} }
} }
console.log('Characteristics', 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]);
@ -683,23 +754,23 @@ class PlejBLE extends EventEmitter {
} }
if (!this.plejdService) { if (!this.plejdService) {
logger.info("warning: wasn't able to connect to Plejd, will retry."); logger.warn("Wasn't able to connect to Plejd, will retry.");
this.emit('connectFailed'); return null;
return;
} }
if (!this.characteristics.auth) { if (!this.characteristics.auth) {
logger.error('unable to enumerate characteristics.'); logger.error('unable to enumerate characteristics.');
this.emit('connectFailed'); return null;
return;
} }
this.connectedDevice = device.device; this.connectedDevice = device.device;
await this.authenticate(); await this.authenticate();
return this.connectedDevice;
} }
// eslint-disable-next-line no-unused-vars // eslint-disable-next-line no-unused-vars
async onLastDataUpdated(iface, properties, invalidated) { async onLastDataUpdated(iface, properties) {
if (iface !== GATT_CHRC_ID) { if (iface !== GATT_CHRC_ID) {
return; return;
} }
@ -734,7 +805,7 @@ class PlejBLE extends EventEmitter {
const dim = decoded.length > 7 ? decoded.readUInt8(7) : 0; const dim = decoded.length > 7 ? decoded.readUInt8(7) : 0;
// Bytes 8-9 are sometimes present, what are they? // Bytes 8-9 are sometimes present, what are they?
const deviceName = this._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.debug(`Raw event received: ${decoded.toString('hex')}`);
@ -766,7 +837,7 @@ class PlejBLE extends EventEmitter {
logger.verbose(`All states: ${this.plejdDevices}`); logger.verbose(`All states: ${this.plejdDevices}`);
} else if (cmd === BLE_CMD_SCENE_TRIG) { } else if (cmd === BLE_CMD_SCENE_TRIG) {
const sceneId = state; const sceneId = state;
const sceneName = this._getDeviceName(sceneId); const sceneName = this.deviceRegistry.getSceneName(sceneId);
logger.debug( logger.debug(
`${sceneName} (${sceneId}) scene triggered (device id ${deviceId}). Name can be misleading if there is a device with the same numeric id.`, `${sceneName} (${sceneId}) scene triggered (device id ${deviceId}). Name can be misleading if there is a device with the same numeric id.`,
@ -784,14 +855,6 @@ class PlejBLE extends EventEmitter {
} }
} }
wireEvents() {
logger.info('wireEvents()');
const self = this;
this.on('pingFailed', this.onPingFailed.bind(self));
this.on('pingSuccess', this.onPingSuccess.bind(self));
}
// eslint-disable-next-line class-methods-use-this // eslint-disable-next-line class-methods-use-this
_createChallengeResponse(key, challenge) { _createChallengeResponse(key, challenge) {
const intermediate = crypto.createHash('sha256').update(xor(key, challenge)).digest(); const intermediate = crypto.createHash('sha256').update(xor(key, challenge)).digest();
@ -836,4 +899,4 @@ class PlejBLE extends EventEmitter {
} }
} }
module.exports = PlejBLE; module.exports = PlejBLEHandler;