diff --git a/lib/extension/availability.ts b/lib/extension/availability.ts index 789a48a96..380d420ee 100644 --- a/lib/extension/availability.ts +++ b/lib/extension/availability.ts @@ -1,3 +1,5 @@ +import type * as zhc from 'zigbee-herdsman-converters'; + import type {Zigbee2MQTTAPI} from '../types/api'; import assert from 'node:assert'; @@ -5,8 +7,6 @@ import assert from 'node:assert'; import bind from 'bind-decorator'; import debounce from 'debounce'; -import * as zhc from 'zigbee-herdsman-converters'; - import logger from '../util/logger'; import * as settings from '../util/settings'; import utils from '../util/utils'; @@ -19,9 +19,16 @@ const RETRIEVE_ON_RECONNECT: readonly {keys: string[]; condition?: (state: KeyVa ]; export default class Availability extends Extension { - private timers: {[s: string]: NodeJS.Timeout} = {}; - private availabilityCache: {[s: string]: boolean} = {}; - private retrieveStateDebouncers: {[s: string]: () => void} = {}; + /** Mapped by IEEE address */ + private readonly timers: Map = new Map(); + /** Mapped by IEEE address or Group ID */ + private readonly lastPublishedAvailabilities: Map = new Map(); + /** Mapped by IEEE address */ + private readonly pingBackoffs: Map = new Map(); + /** IEEE addresses, waiting for last seen changes to take them out of "availability sleep" */ + private readonly backoffPausedDevices: Set = new Set(); + /** Mapped by IEEE address */ + private readonly retrieveStateDebouncers: Map void> = new Map(); private pingQueue: Device[] = []; private pingQueueExecuting = false; private stopped = false; @@ -31,37 +38,95 @@ export default class Availability extends Extension { return utils.minutes(device.options.availability.timeout); } - const type = this.isActiveDevice(device) ? 'active' : 'passive'; + return utils.minutes(this.isActiveDevice(device) ? settings.get().availability.active.timeout : settings.get().availability.passive.timeout); + } - return utils.minutes(settings.get().availability[type].timeout); + private getMaxJitter(device: Device): number { + if (typeof device.options.availability === 'object' && device.options.availability?.max_jitter != null) { + return device.options.availability.max_jitter; + } + + return settings.get().availability.active.max_jitter; + } + + private getBackoff(device: Device): boolean { + if (typeof device.options.availability === 'object' && device.options.availability?.backoff != null) { + return device.options.availability.backoff; + } + + return settings.get().availability.active.backoff; + } + + private getPauseOnBackoffGt(device: Device): number { + if (typeof device.options.availability === 'object' && device.options.availability?.pause_on_backoff_gt != null) { + return device.options.availability.pause_on_backoff_gt; + } + + return settings.get().availability.active.pause_on_backoff_gt; } private isActiveDevice(device: Device): boolean { - return (device.zh.type === 'Router' && device.zh.powerSource !== 'Battery') || device.zh.powerSource === 'Mains (single phase)'; + return ( + (device.zh.type === 'Router' && device.zh.powerSource !== 'Battery') || + (device.zh.powerSource !== undefined && device.zh.powerSource !== 'Unknown' && device.zh.powerSource !== 'Battery') + ); } private isAvailable(entity: Device | Group): boolean { if (entity.isDevice()) { - return Date.now() - (entity.zh.lastSeen ?? /* v8 ignore next */ 0) < this.getTimeout(entity); - } else { - const membersDevices = entity.membersDevices(); - return membersDevices.length === 0 || membersDevices.some((d) => this.availabilityCache[d.ieeeAddr]); + const lastSeen = entity.zh.lastSeen ?? /* v8 ignore next */ 0; + + return Date.now() - lastSeen < this.getTimeout(entity) + this.getMaxJitter(entity); } + + for (const memberDevice of entity.membersDevices()) { + if (this.lastPublishedAvailabilities.get(memberDevice.ieeeAddr) === true) { + return true; + } + } + + return false; } - private resetTimer(device: Device): void { - clearTimeout(this.timers[device.ieeeAddr]); + private resetTimer(device: Device, resetBackoff = false): void { + clearTimeout(this.timers.get(device.ieeeAddr)); this.removeFromPingQueue(device); // If the timer triggers, the device is not available anymore otherwise resetTimer already has been called if (this.isActiveDevice(device)) { - // If device did not check in, ping it, if that fails it will be marked as offline - this.timers[device.ieeeAddr] = setTimeout(() => this.addToPingQueue(device), this.getTimeout(device) + utils.seconds(1)); + const backoffEnabled = this.getBackoff(device); + const jitter = Math.random() * this.getMaxJitter(device); + let backoff = 1; + + if (resetBackoff) { + // always cleanup even if backoff disabled (ensures proper state if changed at runtime) + this.backoffPausedDevices.delete(device.ieeeAddr); + this.pingBackoffs.delete(device.ieeeAddr); + } else if (backoffEnabled) { + backoff = this.pingBackoffs.get(device.ieeeAddr) ?? 1; + } + + // never paused if was reset (just deleted) or backoff disabled, might as well skip the Set lookup + if (!backoffEnabled || resetBackoff || !this.backoffPausedDevices.has(device.ieeeAddr)) { + // If device did not check in, ping it, if that fails it will be marked as offline + this.timers.set( + device.ieeeAddr, + setTimeout(this.addToPingQueue.bind(this, device), (this.getTimeout(device) + utils.seconds(1) + jitter) * backoff), + ); + } } else { - this.timers[device.ieeeAddr] = setTimeout(() => this.publishAvailability(device, true), this.getTimeout(device) + utils.seconds(1)); + this.timers.set( + device.ieeeAddr, + setTimeout(this.publishAvailability.bind(this, device, true), this.getTimeout(device) + utils.seconds(1)), + ); } } + private clearTimer(ieeeAddress: string): void { + clearTimeout(this.timers.get(ieeeAddress)); + this.timers.delete(ieeeAddress); + } + private addToPingQueue(device: Device): void { this.pingQueue.push(device); this.pingQueueExecuteNext().catch(utils.noop); @@ -69,7 +134,7 @@ export default class Availability extends Extension { private removeFromPingQueue(device: Device): void { const index = this.pingQueue.findIndex((d) => d.ieeeAddr === device.ieeeAddr); - if (index != -1) { + if (index !== -1) { this.pingQueue.splice(index, 1); } } @@ -81,8 +146,8 @@ export default class Availability extends Extension { this.pingQueueExecuting = true; const device = this.pingQueue[0]; - let pingedSuccessfully = false; - const available = this.availabilityCache[device.ieeeAddr] || this.isAvailable(device); + let pingSuccess = false; + const available = this.lastPublishedAvailabilities.get(device.ieeeAddr) || this.isAvailable(device); const attempts = available ? 2 : 1; for (let i = 1; i <= attempts; i++) { @@ -90,7 +155,7 @@ export default class Availability extends Extension { // Enable recovery if device is marked as available and first ping fails. await device.zh.ping(!available || i !== 2); - pingedSuccessfully = true; + pingSuccess = true; logger.debug(`Successfully pinged '${device.name}' (attempt ${i}/${attempts})`); break; @@ -109,8 +174,21 @@ export default class Availability extends Extension { return; } - await this.publishAvailability(device, !pingedSuccessfully); - this.resetTimer(device); + if (!pingSuccess && this.getBackoff(device)) { + const currentBackoff = this.pingBackoffs.get(device.ieeeAddr) ?? 1; + // setting is "greater than" but since we already did the ping, we use ">=" for comparison below (pause next) + const pauseOnBackoff = this.getPauseOnBackoffGt(device); + + if (pauseOnBackoff > 0 && currentBackoff >= pauseOnBackoff) { + this.backoffPausedDevices.add(device.ieeeAddr); + } else { + // results in backoffs: *1.5, *3, *6, *12... (with default timeout: 10, 15, 30, 60, 120) + this.pingBackoffs.set(device.ieeeAddr, currentBackoff * (available ? 1.5 : 2)); + } + } + + await this.publishAvailability(device, !pingSuccess); + this.resetTimer(device, pingSuccess); this.removeFromPingQueue(device); // Sleep 2 seconds before executing next ping @@ -132,12 +210,12 @@ export default class Availability extends Extension { await this.publishAvailability(data.entity, false, true); } }); - - this.eventBus.onEntityRemoved(this, (data) => data.type == 'device' && clearTimeout(this.timers[data.id])); - this.eventBus.onDeviceLeave(this, (data) => clearTimeout(this.timers[data.ieeeAddr])); + this.eventBus.onEntityRemoved(this, (data) => data.type === 'device' && this.clearTimer(data.id)); + this.eventBus.onDeviceLeave(this, (data) => this.clearTimer(data.ieeeAddr)); this.eventBus.onDeviceAnnounce(this, (data) => this.retrieveState(data.device)); this.eventBus.onLastSeenChanged(this, this.onLastSeenChanged); this.eventBus.onGroupMembersChanged(this, (data) => this.publishAvailability(data.group, false)); + // Publish initial availability await this.publishAvailabilityForAllEntities(); @@ -154,7 +232,7 @@ export default class Availability extends Extension { } } - @bind private async publishAvailabilityForAllEntities(): Promise { + private async publishAvailabilityForAllEntities(): Promise { for (const entity of this.zigbee.devicesAndGroupsIterator(utils.deviceNotCoordinator)) { if (utils.isAvailabilityEnabledForEntity(entity, settings.get())) { await this.publishAvailability(entity, true, false, true); @@ -175,18 +253,18 @@ export default class Availability extends Extension { const available = this.isAvailable(entity); - if (!forcePublish && this.availabilityCache[entity.ID] == available) { + if (!forcePublish && this.lastPublishedAvailabilities.get(entity.ID) === available) { return; } - if (entity.isDevice() && entity.ieeeAddr in this.availabilityCache && available && this.availabilityCache[entity.ieeeAddr] === false) { + if (entity.isDevice() && available && this.lastPublishedAvailabilities.get(entity.ieeeAddr) === false) { logger.debug(`Device '${entity.name}' reconnected`); this.retrieveState(entity); } const topic = `${entity.name}/availability`; const payload: Zigbee2MQTTAPI['{friendlyName}/availability'] = {state: available ? 'online' : 'offline'}; - this.availabilityCache[entity.ID] = available; + this.lastPublishedAvailabilities.set(entity.ID, available); await this.mqtt.publish(topic, JSON.stringify(payload), {retain: true, qos: 1}); if (!skipGroups && entity.isDevice()) { @@ -202,7 +280,7 @@ export default class Availability extends Extension { if (utils.isAvailabilityEnabledForEntity(data.device, settings.get())) { // Remove from ping queue, not necessary anymore since we know the device is online. this.removeFromPingQueue(data.device); - this.resetTimer(data.device); + this.resetTimer(data.device, true); await this.publishAvailability(data.device, false); } } @@ -211,7 +289,7 @@ export default class Availability extends Extension { this.stopped = true; this.pingQueue = []; - for (const t of Object.values(this.timers)) { + for (const [, t] of this.timers) { clearTimeout(t); } @@ -223,43 +301,46 @@ export default class Availability extends Extension { * Retrieve state of a device in a debounced manner, this function is called on a 'deviceAnnounce' which a * device can send multiple times after each other. */ - if (device.definition && !device.zh.interviewing && !this.retrieveStateDebouncers[device.ieeeAddr]) { - this.retrieveStateDebouncers[device.ieeeAddr] = debounce(async () => { - logger.debug(`Retrieving state of '${device.name}' after reconnect`); + if (device.definition && !device.zh.interviewing && !this.retrieveStateDebouncers.get(device.ieeeAddr)) { + this.retrieveStateDebouncers.set( + device.ieeeAddr, + debounce(async () => { + logger.debug(`Retrieving state of '${device.name}' after reconnect`); - // Color and color temperature converters do both, only needs to be called once. - for (const item of RETRIEVE_ON_RECONNECT) { - if (item.condition && this.state.get(device) && !item.condition(this.state.get(device))) { - continue; + // Color and color temperature converters do both, only needs to be called once. + for (const item of RETRIEVE_ON_RECONNECT) { + if (item.condition && this.state.get(device) && !item.condition(this.state.get(device))) { + continue; + } + + const converter = device.definition!.toZigbee.find((c) => !c.key || c.key.find((k) => item.keys.includes(k))); + const options: KeyValue = device.options; + const state = this.state.get(device); + const meta: zhc.Tz.Meta = { + message: this.state.get(device), + mapped: device.definition!, + endpoint_name: undefined, + options, + state, + device: device.zh, + /* v8 ignore next */ + publish: (payload: KeyValue) => this.publishEntityState(device, payload), + }; + + try { + const endpoint = device.endpoint(); + assert(endpoint); + await converter?.convertGet?.(endpoint, item.keys[0], meta); + } catch (error) { + logger.error(`Failed to read state of '${device.name}' after reconnect (${(error as Error).message})`); + } + + await utils.sleep(500); } - - const converter = device.definition!.toZigbee.find((c) => !c.key || c.key.find((k) => item.keys.includes(k))); - const options: KeyValue = device.options; - const state = this.state.get(device); - const meta: zhc.Tz.Meta = { - message: this.state.get(device), - mapped: device.definition!, - endpoint_name: undefined, - options, - state, - device: device.zh, - /* v8 ignore next */ - publish: (payload: KeyValue) => this.publishEntityState(device, payload), - }; - - try { - const endpoint = device.endpoint(); - assert(endpoint); - await converter?.convertGet?.(endpoint, item.keys[0], meta); - } catch (error) { - logger.error(`Failed to read state of '${device.name}' after reconnect (${(error as Error).message})`); - } - - await utils.sleep(500); - } - }, utils.seconds(2)); + }, utils.seconds(2)), + ); } - this.retrieveStateDebouncers[device.ieeeAddr]?.(); + this.retrieveStateDebouncers.get(device.ieeeAddr)?.(); } } diff --git a/lib/extension/bridge.ts b/lib/extension/bridge.ts index 371d37861..52e458360 100644 --- a/lib/extension/bridge.ts +++ b/lib/extension/bridge.ts @@ -592,9 +592,8 @@ export default class Bridge extends Extension { ): Promise> { const ID = typeof message === 'object' ? message.id : message.trim(); const entity = this.getEntity(entityType, ID); + // note: entity.name is dynamically retrieved, will change once device is removed (friendly => ieee) const friendlyName = entity.name; - const entityID = entity.ID; - let block = false; let force = false; let blockForceLog = ''; @@ -609,8 +608,7 @@ export default class Bridge extends Extension { } try { - logger.info(`Removing ${entityType} '${entity.name}'${blockForceLog}`); - const name = entity.name; + logger.info(`Removing ${entityType} '${friendlyName}'${blockForceLog}`); if (entity instanceof Device) { if (block) { @@ -623,8 +621,8 @@ export default class Bridge extends Extension { await entity.zh.removeFromNetwork(); } - this.eventBus.emitEntityRemoved({id: entityID, name, type: 'device'}); - settings.removeDevice(entityID as string); + this.eventBus.emitEntityRemoved({id: entity.ID, name: friendlyName, type: 'device'}); + settings.removeDevice(entity.ID as string); } else { if (force) { entity.zh.removeFromDatabase(); @@ -632,12 +630,12 @@ export default class Bridge extends Extension { await entity.zh.removeFromNetwork(); } - this.eventBus.emitEntityRemoved({id: entityID, name, type: 'group'}); - settings.removeGroup(entityID); + this.eventBus.emitEntityRemoved({id: entity.ID, name: friendlyName, type: 'group'}); + settings.removeGroup(entity.ID); } // Remove from state - this.state.remove(entityID); + this.state.remove(entity.ID); // Clear any retained messages await this.mqtt.publish(friendlyName, '', {retain: true}); @@ -694,7 +692,7 @@ export default class Bridge extends Extension { zigbee_herdsman_converters: this.zigbeeHerdsmanConvertersVersion, zigbee_herdsman: this.zigbeeHerdsmanVersion, coordinator: { - ieee_address: this.zigbee.firstCoordinatorEndpoint().getDevice().ieeeAddr, + ieee_address: this.zigbee.firstCoordinatorEndpoint().deviceIeeeAddress, ...this.coordinatorVersion, }, network: { @@ -732,7 +730,7 @@ export default class Bridge extends Extension { for (const bind of endpoint.binds) { const target = utils.isZHEndpoint(bind.target) - ? {type: 'endpoint', ieee_address: bind.target.getDevice().ieeeAddr, endpoint: bind.target.ID} + ? {type: 'endpoint', ieee_address: bind.target.deviceIeeeAddress, endpoint: bind.target.ID} : {type: 'group', id: bind.target.groupID}; data.bindings.push({cluster: bind.cluster.name, target}); } @@ -780,7 +778,7 @@ export default class Bridge extends Extension { const members = []; for (const member of group.zh.members) { - members.push({ieee_address: member.getDevice().ieeeAddr, endpoint: member.ID}); + members.push({ieee_address: member.deviceIeeeAddress, endpoint: member.ID}); } groups.push({ diff --git a/lib/extension/publish.ts b/lib/extension/publish.ts index 19a1c5e72..c7687e2ed 100644 --- a/lib/extension/publish.ts +++ b/lib/extension/publish.ts @@ -134,9 +134,7 @@ export default class Publish extends Extension { const entityState = this.state.get(re); const membersState = re instanceof Group - ? Object.fromEntries( - re.zh.members.map((e) => [e.getDevice().ieeeAddr, this.state.get(this.zigbee.resolveEntity(e.getDevice().ieeeAddr)!)]), - ) + ? Object.fromEntries(re.zh.members.map((e) => [e.deviceIeeeAddress, this.state.get(this.zigbee.resolveEntity(e.deviceIeeeAddress)!)])) : undefined; const converters = this.getDefinitionConverters(definition); diff --git a/lib/model/group.ts b/lib/model/group.ts index 2fbc51c2d..263ec1f1e 100644 --- a/lib/model/group.ts +++ b/lib/model/group.ts @@ -26,8 +26,10 @@ export default class Group { return !!device.zh.endpoints.find((e) => this.zh.members.includes(e)); } - membersDevices(): Device[] { - return this.zh.members.map((d) => this.resolveDevice(d.getDevice().ieeeAddr)!); + *membersDevices(): Generator { + for (const member of this.zh.members) { + yield this.resolveDevice(member.deviceIeeeAddress)!; + } } membersDefinitions(): zhc.Definition[] { diff --git a/lib/types/types.d.ts b/lib/types/types.d.ts index 692b03e20..680b9b903 100644 --- a/lib/types/types.d.ts +++ b/lib/types/types.d.ts @@ -48,7 +48,7 @@ declare global { namespace eventdata { type EntityRenamed = {entity: Device | Group; homeAssisantRename: boolean; from: string; to: string}; - type EntityRemoved = {id: number | string; name: string; type: 'device' | 'group'}; + type EntityRemoved = {id: string; name: string; type: 'device'} | {id: number; name: string; type: 'group'}; type MQTTMessage = {topic: string; message: string}; type MQTTMessagePublished = {topic: string; payload: string; options: {retain: boolean; qos: number}}; type StateChange = { @@ -98,7 +98,12 @@ declare global { }; availability: { enabled: boolean; - active: {timeout: number}; + active: { + timeout: number; + max_jitter: number; + backoff: boolean; + pause_on_backoff_gt: number; + }; passive: {timeout: number}; }; mqtt: { @@ -200,7 +205,14 @@ declare global { interface DeviceOptions { disabled?: boolean; retention?: number; - availability?: boolean | {timeout: number}; + availability?: + | boolean + | { + timeout: number; + max_jitter?: number; + backoff?: boolean; + pause_on_backoff_gt?: number; + }; optimistic?: boolean; debounce?: number; debounce_ignore?: string[]; diff --git a/lib/util/settings.schema.json b/lib/util/settings.schema.json index 7804bc8c4..98a4ecc5d 100644 --- a/lib/util/settings.schema.json +++ b/lib/util/settings.schema.json @@ -68,6 +68,26 @@ "requiresRestart": true, "default": 10, "description": "Time after which an active device will be marked as offline in minutes" + }, + "max_jitter": { + "type": "number", + "title": "Max jitter", + "default": 30000, + "minimum": 1000, + "description": "Maximum jitter (in msec) allowed on timeout to avoid availability pings trying to trigger around the same time" + }, + "backoff": { + "type": "boolean", + "title": "Enabled", + "description": "Enable timeout backoff on failed availability pings (x1.5, x3, x6, x12...)", + "default": true + }, + "pause_on_backoff_gt": { + "type": "number", + "title": "Pause on backoff greater than", + "default": 0, + "minimum": 0, + "description": "Pause availability pings when backoff reaches over this limit until a new Zigbee message is received from the device. A value of zero disables pausing." } }, "required": ["timeout"] diff --git a/lib/util/settings.ts b/lib/util/settings.ts index d387e3806..484fd5a52 100644 --- a/lib/util/settings.ts +++ b/lib/util/settings.ts @@ -38,7 +38,7 @@ export const defaults: RecursivePartial = { }, availability: { enabled: false, - active: {timeout: 10}, + active: {timeout: 10, max_jitter: 30000, backoff: true, pause_on_backoff_gt: 0}, passive: {timeout: 1500}, }, frontend: { diff --git a/lib/util/utils.ts b/lib/util/utils.ts index 21487cf3b..3f9cbdbc0 100644 --- a/lib/util/utils.ts +++ b/lib/util/utils.ts @@ -247,18 +247,20 @@ function isAvailabilityEnabledForEntity(entity: Device | Group, settings: Settin } if (entity.isGroup()) { - return !entity.membersDevices().some((d) => !isAvailabilityEnabledForEntity(d, settings)); + for (const memberDevice of entity.membersDevices()) { + if (!isAvailabilityEnabledForEntity(memberDevice, settings)) { + return false; + } + } + + return true; } if (entity.options.availability != null) { return !!entity.options.availability; } - if (!settings.availability.enabled) { - return false; - } - - return true; + return settings.availability.enabled; } function isZHEndpoint(obj: unknown): obj is zh.Endpoint { diff --git a/test/extensions/availability.test.ts b/test/extensions/availability.test.ts index 2c509d2db..24c1edfd5 100644 --- a/test/extensions/availability.test.ts +++ b/test/extensions/availability.test.ts @@ -57,6 +57,9 @@ describe('Extension: Availability', () => { settings.reRead(); settings.set(['availability'], {enabled: true}); settings.set(['devices', devices.bulb_color_2.ieeeAddr, 'availability'], false); + settings.set(['devices', devices.hue_twilight.ieeeAddr, 'availability'], {max_jitter: 1000}); + settings.set(['devices', devices.GLEDOPTO_2ID.ieeeAddr, 'availability'], {backoff: false}); + settings.set(['devices', devices.QBKG03LM.ieeeAddr, 'availability'], {pause_on_backoff_gt: 1.5}); Object.values(devices).forEach((d) => (d.lastSeen = utils.minutes(1))); mocksClear.forEach((m) => m.mockClear()); await resetExtension(); @@ -137,7 +140,7 @@ describe('Extension: Availability', () => { it('Should reset ping timer when device last seen changes for active device', async () => { mockMQTTPublishAsync.mockClear(); - await setTimeAndAdvanceTimers(utils.minutes(5)); + await setTimeAndAdvanceTimers(utils.minutes(6)); expect(devices.bulb_color.ping).toHaveBeenCalledTimes(0); await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); @@ -390,4 +393,289 @@ describe('Extension: Availability', () => { await expect(() => availability.start()).rejects.toThrow(); }); + + it('jitters pings', async () => { + const devicesPings = [ + devices.bulb_color.ping, + devices.TS0601_thermostat.ping, + devices.bulb_2.ping, + devices.ZNCZ02LM.ping, + devices.GLEDOPTO_2ID.ping, + devices.QBKG03LM.ping, + devices.hue_twilight.ping, + ]; + let called = 0; + let lastCalled = 0; + + await setTimeAndAdvanceTimers(utils.minutes(10)); + + for (const p of devicesPings) { + called += p.mock.calls.length; + } + + expect(called).toStrictEqual(0); + + lastCalled = called; + called = 0; + + await setTimeAndAdvanceTimers(utils.seconds(2)); // 10:02 + + expect(devices.hue_twilight.ping).toHaveBeenCalledTimes(1); // max_jitter: 1000 + + await setTimeAndAdvanceTimers(utils.seconds(8)); // 10:10 + + for (const p of devicesPings) { + called += p.mock.calls.length; + } + + expect(called).toBeGreaterThanOrEqual(0); + expect(called).toBeLessThan(7); + expect(called).toBeGreaterThanOrEqual(lastCalled); + + lastCalled = called; + called = 0; + + await setTimeAndAdvanceTimers(utils.seconds(20)); // 10:20 + + for (const p of devicesPings) { + called += p.mock.calls.length; + } + + expect(called).toBeGreaterThanOrEqual(lastCalled); + + lastCalled = called; + called = 0; + await setTimeAndAdvanceTimers(utils.seconds(35)); // 10:35 + + for (const p of devicesPings) { + called += p.mock.calls.length; + } + + expect(called).toStrictEqual(7); + + for (const p of devicesPings) { + expect(p).toHaveBeenCalledTimes(1); + } + }); + + it('does not trigger backoff on ping success', async () => { + settings.set(['availability', 'active', 'max_jitter'], 0); // easier testing + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 10:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(1); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(1, true); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 21:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + }); + + it('triggers backoff on successive ping failures', async () => { + settings.set(['availability', 'active', 'max_jitter'], 0); // easier testing + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + await mockZHEvents.lastSeenChanged({device: devices.GLEDOPTO_2ID}); // backoff: false + + devices.bulb_color.ping + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }); + devices.GLEDOPTO_2ID.ping + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 10:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(1, true); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(2, false); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(2); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenNthCalledWith(1, true); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenNthCalledWith(2, false); + + await setTimeAndAdvanceTimers(utils.minutes(14.5)); // 25:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 25:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(29.5)); // 55:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(6); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 55:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(6); + + await setTimeAndAdvanceTimers(utils.minutes(59.5)); // 115:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(12); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 115:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(5); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(12); + + // backoff was reset (4 mocks done) + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 126:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(6); + expect(devices.GLEDOPTO_2ID.ping).toHaveBeenCalledTimes(13); + }); + + it('resets backoff on last seen', async () => { + settings.set(['availability', 'active', 'max_jitter'], 0); // easier testing + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + + devices.bulb_color.ping + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 10:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(1, true); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(2, false); + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 21:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + }); + + it('pauses when backoff reaches configured value and unpauses on last seen', async () => { + settings.set(['availability', 'active', 'max_jitter'], 0); // easier testing + settings.set(['availability', 'active', 'pause_on_backoff_gt'], 3); + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + await mockZHEvents.lastSeenChanged({device: devices.QBKG03LM}); // pause_on_backoff_gt: 1.5 + + devices.bulb_color.ping + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }); + devices.QBKG03LM.ping + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 10:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(1, true); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(2, false); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(2); + expect(devices.QBKG03LM.ping).toHaveBeenNthCalledWith(1, true); + expect(devices.QBKG03LM.ping).toHaveBeenNthCalledWith(2, false); + + await setTimeAndAdvanceTimers(utils.minutes(14.5)); // 25:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(2); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 25:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(29.5)); // 55:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 55:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(100)); + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(100)); + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(3); + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + await mockZHEvents.lastSeenChanged({device: devices.QBKG03LM}); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(5); + expect(devices.QBKG03LM.ping).toHaveBeenCalledTimes(4); + }); + + it('allows to disable backoff', async () => { + settings.set(['availability', 'active', 'max_jitter'], 0); // easier testing + settings.set(['availability', 'active', 'backoff'], false); + + await mockZHEvents.lastSeenChanged({device: devices.bulb_color}); + + devices.bulb_color.ping + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }) + .mockImplementationOnce(() => { + throw new Error('failed'); + }); + + await setTimeAndAdvanceTimers(utils.minutes(10.5)); // 10:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(1, true); + expect(devices.bulb_color.ping).toHaveBeenNthCalledWith(2, false); + + await setTimeAndAdvanceTimers(utils.minutes(9.5)); // 20:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(2); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 20:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(9.5)); // 30:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(3); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 30:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + + await setTimeAndAdvanceTimers(utils.minutes(9.5)); // 40:00 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(4); + + await setTimeAndAdvanceTimers(utils.minutes(0.5)); // 40:30 + expect(devices.bulb_color.ping).toHaveBeenCalledTimes(5); + }); }); diff --git a/test/extensions/bridge.test.ts b/test/extensions/bridge.test.ts index 9b927c3f1..48f2e4b52 100644 --- a/test/extensions/bridge.test.ts +++ b/test/extensions/bridge.test.ts @@ -258,7 +258,12 @@ describe('Extension: Bridge', () => { }, availability: { enabled: false, - active: {timeout: 10}, + active: { + timeout: 10, + max_jitter: 30000, + backoff: true, + pause_on_backoff_gt: 0, + }, passive: {timeout: 1500}, }, frontend: { diff --git a/test/mocks/zigbeeHerdsman.ts b/test/mocks/zigbeeHerdsman.ts index d20db08ec..6d4ff214f 100644 --- a/test/mocks/zigbeeHerdsman.ts +++ b/test/mocks/zigbeeHerdsman.ts @@ -236,7 +236,7 @@ export class Device { interview: Mock; interviewing: boolean; meta: Record; - ping: Mock; + ping: Mock<(disableRecovery?: boolean) => Promise>; removeFromNetwork: Mock; removeFromDatabase: Mock; customClusters: Record; @@ -1141,7 +1141,7 @@ export const devices = { '0x00124b00cfcf3298', 18129, 0xfff1, - [new Endpoint(8, [0, 3, 4, 5, 6, 8], []), new Endpoint(242, [], [33])], + [new Endpoint(8, [0, 3, 4, 5, 6, 8], [], '0x00124b00cfcf3298'), new Endpoint(242, [], [33], '0x00124b00cfcf3298')], true, 'DC Source', 'FanBee1', @@ -1169,7 +1169,8 @@ export const mockController = { (): Promise => Promise.resolve({type: 'z-Stack', meta: {version: 1, revision: 20190425}}), ), getNetworkParameters: vi.fn( - (): Promise => Promise.resolve({panID: 0x162a, extendedPanID: '0x64c5fd698daf0c00', channel: 15}), + (): Promise => + Promise.resolve({panID: 0x162a, extendedPanID: '0x64c5fd698daf0c00', channel: 15, nwkUpdateID: 0}), ), getDevices: vi.fn((): Device[] => []), getDevicesIterator: vi.fn(function* (predicate?: (value: Device) => boolean): Generator {