Major OTA improvements. https://github.com/Koenkk/zigbee2mqtt/issues/2921

lib/extension/homeassistant.js

@@ -1203,6 +1203,7 @@ const mapping = {
     'GP-LBU019BBAWU': [cfg.light_brightness],
     '371000001': [cfg.light_brightness_colortemp],
     '10011725': [cfg.light_brightness_colortemp_colorxy],
+    '929002277501': [cfg.light_brightness],
 };
 
 Object.keys(mapping).forEach((key) => {

lib/extension/otaUpdate.js

@@ -5,11 +5,29 @@ const topicRegex = new RegExp(`^${settings.get().mqtt.base_topic}/bridge/ota_upd
 const BaseExtension = require('./baseExtension');
 
 class OTAUpdate extends BaseExtension {
+    constructor(zigbee, mqtt, state, publishEntityState, eventBus) {
+        super(zigbee, mqtt, state, publishEntityState, eventBus);
+        this.inProgress = new Set();
+    }
+
     onMQTTConnected() {
         this.mqtt.subscribe(`${settings.get().mqtt.base_topic}/bridge/ota_update/check`);
         this.mqtt.subscribe(`${settings.get().mqtt.base_topic}/bridge/ota_update/update`);
     }
 
+    async readSoftwareBuildIDAndDateCode(device, update) {
+        const endpoint = device.endpoints.find((e) => e.supportsInputCluster('genBasic'));
+        const result = await endpoint.read('genBasic', ['dateCode', 'swBuildId']);
+
+        if (update) {
+            device.softwareBuildID = result.swBuildId;
+            device.dateCode = result.dateCode;
+            device.save();
+        }
+
+        return {softwareBuildID: result.swBuildId, dateCode: result.dateCode};
+    }
+
     async onMQTTMessage(topic, message) {
         if (!topic.match(topicRegex)) {
             return null;
@@ -23,25 +41,46 @@ class OTAUpdate extends BaseExtension {
             return;
         }
 
-        logger.info(`Checking if update available for '${device.name}'`);
+        if (this.inProgress.has(device.device.ieeeAddr)) {
+            logger.error(`Update or check already in progress for '${device.name}', skipping...`);
+            return;
+        }
+        this.inProgress.add(device.device.ieeeAddr);
 
-        const updateAvailable = await device.mapped.ota.isUpdateAvailable(device.device, logger);
         const type = topic.split('/')[3];
+        if (type === 'check') {
+            logger.info(`Checking if update available for '${device.name}'`);
+            try {
+                const available = await device.mapped.ota.isUpdateAvailable(device.device, logger);
+                logger.info(available ?
+                    `Update available for '${device.name}'` : `No update available for '${device.name}'`,
+                );
+            } catch (error) {
+                logger.error(`Failed to check if update available for '${device.name}' (${error.message})`);
+            }
+        } else { // type === 'update'
+            logger.info(`Updating '${device.name}' to latest firmware`);
+            try {
+                const onProgress = (progress, remaining) => {
+                    let message = `Update of '${device.name}' at ${progress}%`;
+                    if (remaining) {
+                        message += `, +- ${Math.round(remaining / 60)} minutes remaining`;
+                    }
 
-        if (updateAvailable) {
-            logger.info(`Update available for '${device.name}'`);
-        } else {
-            const level = type === 'update' ? 'error' : 'info';
-            logger[level](`No update available for '${device.name}'`);
+                    logger.info(message);
+                };
+
+                const from_ = await this.readSoftwareBuildIDAndDateCode(device.device, false);
+                await device.mapped.ota.updateToLatest(device.device, logger, onProgress);
+                const to = await this.readSoftwareBuildIDAndDateCode(device.device, true);
+                const [fromS, toS] = [JSON.stringify(from_), JSON.stringify(to)];
+                logger.info(`Finished update of '${device.name}', from '${fromS}' to '${toS}'`);
+            } catch (error) {
+                logger.error(`Update of '${device.name}' failed (${error.message})`);
+            }
         }
 
-        if (type === 'update' && updateAvailable) {
-            logger.info(`Starting update of '${device.name}'`);
-            const onProgress = (progress) => logger.info(`Update of '${device.name}' at ${progress}%`);
-            const result = await device.mapped.ota.updateToLatest(device.device, logger, onProgress);
-            const [from, to] = [JSON.stringify(result.from), JSON.stringify(result.to)];
-            logger.info(`Finished update of '${device.name}', from '${from}' to '${to}'`);
-        }
+        this.inProgress.delete(device.device.ieeeAddr);
     }
 }
 

npm-shrinkwrap.json

@@ -5401,9 +5401,9 @@
       "dev": true
     },
     "rimraf": {
-      "version": "3.0.1",
-      "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-3.0.1.tgz",
-      "integrity": "sha512-IQ4ikL8SjBiEDZfk+DFVwqRK8md24RWMEJkdSlgNLkyyAImcjf8SWvU1qFMDOb4igBClbTQ/ugPqXcRwdFTxZw==",
+      "version": "3.0.2",
+      "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-3.0.2.tgz",
+      "integrity": "sha512-JZkJMZkAGFFPP2YqXZXPbMlMBgsxzE8ILs4lMIX/2o0L9UBw9O/Y3o6wFw/i9YLapcUJWwqbi3kdxIPdC62TIA==",
       "requires": {
         "glob": "^7.1.3"
       }
@@ -6500,9 +6500,9 @@
       "dev": true
     },
     "v8-to-istanbul": {
-      "version": "4.1.1",
-      "resolved": "https://registry.npmjs.org/v8-to-istanbul/-/v8-to-istanbul-4.1.1.tgz",
-      "integrity": "sha512-eDRcudafj/GAV2MSoDNmsV/deeIY9bJ94QuVOzZDEbBd4uX+5v/kODX+p/fqZ74/VYLK1BZv8BPJlNnCV8vDhw==",
+      "version": "4.1.2",
+      "resolved": "https://registry.npmjs.org/v8-to-istanbul/-/v8-to-istanbul-4.1.2.tgz",
+      "integrity": "sha512-G9R+Hpw0ITAmPSr47lSlc5A1uekSYzXxTMlFxso2xoffwo4jQnzbv1p9yXIinO8UMZKfAFewaCHwWvnH4Jb4Ug==",
       "dev": true,
       "requires": {
         "@types/istanbul-lib-coverage": "^2.0.1",
@@ -14750,9 +14750,9 @@
       }
     },
     "zigbee-herdsman-converters": {
-      "version": "12.0.21",
-      "resolved": "https://registry.npmjs.org/zigbee-herdsman-converters/-/zigbee-herdsman-converters-12.0.21.tgz",
-      "integrity": "sha512-lMxv1iT8b25ikoq5crdOMG3r8jIXRH0RKsd3xsi0POK/CcFSySxYvKEbQJXNPVau9ZbKXRUHVTNd/hrRmlaPew==",
+      "version": "12.0.22",
+      "resolved": "https://registry.npmjs.org/zigbee-herdsman-converters/-/zigbee-herdsman-converters-12.0.22.tgz",
+      "integrity": "sha512-x4UfL0pRa6ccCmmoYymliUWbfoiwCEnYsut9/ADuaanhn4LJh1WrTTvO14jmZ0US3kysIoQUh96+Gty1BJ/syg==",
       "requires": {
         "axios": "*"
       },

package.json

@@ -46,7 +46,7 @@
     "semver": "*",
     "winston": "*",
     "zigbee-herdsman": "0.12.46",
-    "zigbee-herdsman-converters": "12.0.21"
+    "zigbee-herdsman-converters": "12.0.22"
   },
   "devDependencies": {
     "eslint": "*",

test/otaUpdate.test.js

@@ -32,51 +32,90 @@ describe('OTA update', () => {
 
     it('Should OTA update a device', async () => {
         const device = zigbeeHerdsman.devices.bulb;
+        const endpoint = device.endpoints[0];
+        let count = 0;
+        endpoint.read.mockImplementation(() => {
+            count++;
+            return {swBuildId: count, dateCode: '2019010' + count}
+        });
         const mapped = zigbeeHerdsmanConverters.findByZigbeeModel(device.modelID)
         mockClear(mapped);
         logger.info.mockClear();
-        mapped.ota.isUpdateAvailable.mockReturnValueOnce(true);
+        logger.error.mockClear();
+        device.save.mockClear();
         mapped.ota.updateToLatest.mockImplementationOnce((a, b, onUpdate) => {
-            onUpdate(2);
-            return {from: {softwareBuildID: 1}, to: {softwareBuildID: 2}};
+            onUpdate(0, null);
+            onUpdate(10, 3600);
         });
 
         MQTT.events.message('zigbee2mqtt/bridge/ota_update/update', 'bulb');
         await flushPromises();
-        expect(logger.info).toHaveBeenCalledWith(`Update available for 'bulb'`);
-        expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(1);
+        expect(logger.info).toHaveBeenCalledWith(`Updating 'bulb' to latest firmware`);
+        expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(0);
         expect(mapped.ota.updateToLatest).toHaveBeenCalledTimes(1);
         expect(mapped.ota.updateToLatest).toHaveBeenCalledWith(device, logger, expect.any(Function));
-        expect(logger.info).toHaveBeenCalledWith(`Update of 'bulb' at 2%`);
-        expect(logger.info).toHaveBeenCalledWith(`Finished update of 'bulb', from '{"softwareBuildID":1}' to '{"softwareBuildID":2}'`);
+        expect(logger.info).toHaveBeenCalledWith(`Update of 'bulb' at 0%`);
+        expect(logger.info).toHaveBeenCalledWith(`Update of 'bulb' at 10%, +- 60 minutes remaining`);
+        expect(logger.info).toHaveBeenCalledWith(`Finished update of 'bulb', from '{"softwareBuildID":1,"dateCode":"20190101"}' to '{"softwareBuildID":2,"dateCode":"20190102"}'`);
+        expect(logger.error).toHaveBeenCalledTimes(0);
+        expect(device.save).toHaveBeenCalledTimes(1);
+        expect(device.dateCode).toBe('20190102');
+        expect(device.softwareBuildID).toBe(2);
     });
 
-    it('Should refuse to OTA update a device when no update is available', async () => {
+    it('Should handle when OTA update fails', async () => {
         const device = zigbeeHerdsman.devices.bulb;
+        const endpoint = device.endpoints[0];
+        endpoint.read.mockImplementation(() => {return {swBuildId: 1, dateCode: '2019010'}});
         const mapped = zigbeeHerdsmanConverters.findByZigbeeModel(device.modelID)
         mockClear(mapped);
         logger.info.mockClear();
-        mapped.ota.isUpdateAvailable.mockReturnValueOnce(false);
+        logger.error.mockClear();
+        device.save.mockClear();
+        mapped.ota.updateToLatest.mockImplementationOnce((a, b, onUpdate) => {
+            throw new Error('Update failed');
+        });
 
         MQTT.events.message('zigbee2mqtt/bridge/ota_update/update', 'bulb');
         await flushPromises();
-        expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(1);
-        expect(mapped.ota.updateToLatest).toHaveBeenCalledTimes(0);
-        expect(logger.error).toHaveBeenCalledWith(`No update available for 'bulb'`);
+        expect(logger.error).toHaveBeenCalledTimes(1);
+        expect(logger.error).toHaveBeenCalledWith(`Update of 'bulb' failed (Update failed)`);
     });
 
     it('Should be able to check if OTA update is available', async () => {
         const device = zigbeeHerdsman.devices.bulb;
         const mapped = zigbeeHerdsmanConverters.findByZigbeeModel(device.modelID)
         mockClear(mapped);
+
         logger.info.mockClear();
         mapped.ota.isUpdateAvailable.mockReturnValueOnce(false);
-
         MQTT.events.message('zigbee2mqtt/bridge/ota_update/check', 'bulb');
         await flushPromises();
         expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(1);
         expect(mapped.ota.updateToLatest).toHaveBeenCalledTimes(0);
         expect(logger.info).toHaveBeenCalledWith(`No update available for 'bulb'`);
+
+        logger.info.mockClear();
+        mapped.ota.isUpdateAvailable.mockReturnValueOnce(true);
+        MQTT.events.message('zigbee2mqtt/bridge/ota_update/check', 'bulb');
+        await flushPromises();
+        expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(2);
+        expect(mapped.ota.updateToLatest).toHaveBeenCalledTimes(0);
+        expect(logger.info).toHaveBeenCalledWith(`Update available for 'bulb'`);
+    });
+
+    it('Should handle if OTA update check fails', async () => {
+        const device = zigbeeHerdsman.devices.bulb;
+        const mapped = zigbeeHerdsmanConverters.findByZigbeeModel(device.modelID)
+        mockClear(mapped);
+        logger.error.mockClear();
+        mapped.ota.isUpdateAvailable.mockImplementationOnce(() => {throw new Error('RF singals disturbed because of dogs barking')});
+
+        MQTT.events.message('zigbee2mqtt/bridge/ota_update/check', 'bulb');
+        await flushPromises();
+        expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(1);
+        expect(mapped.ota.updateToLatest).toHaveBeenCalledTimes(0);
+        expect(logger.error).toHaveBeenCalledWith(`Failed to check if update available for 'bulb' (RF singals disturbed because of dogs barking)`);
     });
 
     it('Should not check for OTA when device does not support it', async () => {
@@ -84,4 +123,24 @@ describe('OTA update', () => {
         await flushPromises();
         expect(logger.error).toHaveBeenCalledWith(`Device 'bulb_color_2' does not support OTA updates`);
     });
+
+    it('Should refuse to check/update when already in progress', async () => {
+        jest.useFakeTimers();
+        const device = zigbeeHerdsman.devices.bulb;
+        const mapped = zigbeeHerdsmanConverters.findByZigbeeModel(device.modelID)
+        mockClear(mapped);
+
+        logger.info.mockClear();
+        mapped.ota.isUpdateAvailable.mockImplementationOnce(() => {
+            return new Promise((resolve, reject) => {setTimeout(() => resolve(), 99999)})
+        });
+        MQTT.events.message('zigbee2mqtt/bridge/ota_update/check', 'bulb');
+        await flushPromises();
+        MQTT.events.message('zigbee2mqtt/bridge/ota_update/check', 'bulb');
+        await flushPromises();
+        expect(mapped.ota.isUpdateAvailable).toHaveBeenCalledTimes(1);
+        expect(logger.error).toHaveBeenCalledWith(`Update or check already in progress for 'bulb', skipping...`);
+        jest.runAllTimers();
+        await flushPromises();
+    });
 });

test/stub/zigbeeHerdsman.js

@@ -12,6 +12,7 @@ class Group {
 }
 
 const clusters = {
+    'genBasic': 0,
     'genScenes': 5,
     'genOnOff': 6,
     'genLevelCtrl': 8,
@@ -34,7 +35,7 @@ class Endpoint {
         this.configureReporting = jest.fn();
         this.binds = binds;
         this.supportsInputCluster = (cluster) => {
-            assert(clusters[cluster], `Undefined '${cluster}'`);
+            assert(clusters[cluster] !== undefined, `Undefined '${cluster}'`);
             return this.inputClusters.includes(clusters[cluster]);
         }