m.poll() triggers duplicate poll calls when interval changes

[sbraz]

Hi again @Koenkk,
I think I found a generic issue with the poll function.

To reproduce, here's what I do with the ZLinky:

• Add a log line here:

  zigbee-herdsman-converters/src/devices/lixee.ts

  Line 1908 in b80ebbd

  const endpoint = device.getEndpoint(1);

• Start with the device's poll interval set to some value, e.g. 7
• Change the value to 8

Logs now show two poll instances running at once:

[2025-10-25 22:31:49] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:02] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:06] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:11] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:13] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:19] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:21] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:27] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:28] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:35] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:36] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:43] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:44] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:50] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:32:52] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:32:58] info:     zhc:lixee: Running poll with interval 7
[2025-10-25 22:33:01] info:     zhc:lixee: Running poll with interval 8
[2025-10-25 22:33:05] info:     zhc:lixee: Running poll with interval 7

My locally-applied patch:

@@ -1830,6 +1830,7 @@
                     "The default poll interval for these is 600 seconds. Set to -1 to disable polling. " +
                     "Polled attributes are those marked as read-only at https://github.com/fairecasoimeme/Zlinky_TIC/"),
                 poll: async (device, options) => {
+                    logger_1.logger.info(`Running poll with interval ${options.measurement_poll_interval}`, NS);
                     const endpoint = device.getEndpoint(1);
                     const measurement_poll_chunk = options?.measurement_poll_chunk ? options.measurement_poll_chunk : 4;
                     utils.assertNumber(measurement_poll_chunk);

[Nerivec]

Does it work properly if you wrap this line:

zigbee-herdsman-converters/src/lib/modernExtend.ts

Line 685 in b80ebbd

setTimer();

like this:

                            if  (globalStore.getValue(event.data.device.ieeeAddr, args.key) === timer) {
                                setTimer();
                            }

---

Note: same pattern is used in lib/tuya.ts, so fix for this is likely to be applicable there too (maybe other places too)

[sbraz]

@Nerivec I'm usin Z2M in a container in Home Assistant OS so I don't know how I could easily patch the modernExtend source itself. Can I just declare another poll function in my external converter and use it there?

[Nerivec]

You can patch the modernExtend JS same way you patched the lixee file previously. Should be in dist/lib/modernExtend.js.
There's no typescript in the snippet above, so, should be fine directly in JS too.

[sbraz]

I didn't actually patch lixee.ts, I compiled it to JS and changed a few lines to make it work as an external converter. That was the best idea I had in mind at the time :D

I'll check how I can directly edit dist/lib/modernExtend.js inside the Z2M container and restart the service without stopping the container. I'll find a way and I'll let you know in a few hours.

[Nerivec]

Probably easier to rewrite the poll modern extend inside your ext. conv. then and call that one, since you already have an ext. conv. for the lixee.

[sbraz]

It's a real pain to test. For some reason, it always fails when I call m.poll() in my converter. But when I copy the poll function to the converter, it fails once, then I restart Z2M and it seems to stops failing.

What I did was:

• Get the JS of the function: docker exec -it addon_45df7312_zigbee2mqtt sed -n '/^function poll/,/^}/p' ./node_modules/.pnpm/zigbee-herdsman-converters@25.35.1/node_modules/zigbee-herdsman-converters/dist/lib/modernExtend.js > poll.orig.js
• Copy the poll() function to the converter twice, one of them contains the fix, the other one doesn't
• Make the converter call the broken version and change the poll interval: it fails (most of the time at least)
• Switch back to calling m.poll()
• Make the converter call the fixed version and change the poll interval: it no longer fails

@@ -1,5 +1,5 @@
-function poll_fixed(args) {
-    logger_1.logger.info(`Entering local poll function (fixed)`, NS);
+function poll_broken(args) {
+    logger_1.logger.info(`Entering local poll function (broken)`, NS);
     const optionKey = args.optionKey ?? `${args.key}_poll_interval`;
     const onEvent = [
         (event) => {
@@ -22,9 +22,7 @@
                             catch (error) {
                                 logger_1.logger.debug(`Poll of '${event.data.device.ieeeAddr}' failed (${error})`, NS);
                             }
-                            if (globalStore.getValue(event.data.device.ieeeAddr, args.key) === timer) {
                                 setTimer();
-                            }
                         }, seconds * 1000);
                         globalStore.putValue(event.data.device.ieeeAddr, args.key, timer);
                     };

Details

```js function poll_broken(args) { logger_1.logger.info(`Entering local poll function (broken)`, NS); const optionKey = args.optionKey ?? `${args.key}_poll_interval`; const onEvent = [ (event) => { if (event.type === "start" || (event.type === "deviceOptionsChanged" && event.data.from[optionKey] !== event.data.to[optionKey])) { let seconds = args.defaultIntervalSeconds; if (args.option) { seconds = (0, utils_1.toNumber)(event.data.options[optionKey] ?? args.defaultIntervalSeconds, optionKey); } clearTimeout(globalStore.getValue(event.data.device.ieeeAddr, args.key)); if (seconds <= 0) { logger_1.logger.debug(`Not polling '${args.key}' for '${event.data.device.ieeeAddr}' since poll interval is <= 0 (got ${seconds})`, NS); } else { logger_1.logger.debug(`Polling '${args.key}' for '${event.data.device.ieeeAddr}' at an interval of ${seconds}`, NS); const setTimer = () =&gt; { const timer = setTimeout(async () =&gt; { try { await args.poll(event.data.device, event.data.options); } catch (error) { logger_1.logger.debug(`Poll of '${event.data.device.ieeeAddr}' failed (${error})`, NS); } setTimer(); }, seconds * 1000); globalStore.putValue(event.data.device.ieeeAddr, args.key, timer); }; setTimer(); } } else if (event.type === "stop") { clearTimeout(globalStore.getValue(event.data.ieeeAddr, args.key)); globalStore.clearValue(event.data.ieeeAddr, args.key); } }, ]; return { onEvent, options: args.option ? [args.option] : [], isModernExtend: true }; }

function poll_fixed(args) {
logger_1.logger.info(Entering local poll function (fixed), NS);
const optionKey = args.optionKey ?? ${args.key}_poll_interval;
const onEvent = [
(event) => {
if (event.type === "start" || (event.type === "deviceOptionsChanged" && event.data.from[optionKey] !== event.data.to[optionKey])) {
let seconds = args.defaultIntervalSeconds;
if (args.option) {
seconds = (0, utils_1.toNumber)(event.data.options[optionKey] ?? args.defaultIntervalSeconds, optionKey);
}
clearTimeout(globalStore.getValue(event.data.device.ieeeAddr, args.key));
if (seconds <= 0) {
logger_1.logger.debug(Not polling '${args.key}' for '${event.data.device.ieeeAddr}' since poll interval is <= 0 (got ${seconds}), NS);
}
else {
logger_1.logger.debug(Polling '${args.key}' for '${event.data.device.ieeeAddr}' at an interval of ${seconds}, NS);
const setTimer = () => {
const timer = setTimeout(async () => {
try {
await args.poll(event.data.device, event.data.options);
}
catch (error) {
logger_1.logger.debug(Poll of '${event.data.device.ieeeAddr}' failed (${error}), NS);
}
if (globalStore.getValue(event.data.device.ieeeAddr, args.key) === timer) {
setTimer();
}
}, seconds * 1000);
globalStore.putValue(event.data.device.ieeeAddr, args.key, timer);
};
setTimer();
}
}
else if (event.type === "stop") {
clearTimeout(globalStore.getValue(event.data.ieeeAddr, args.key));
globalStore.clearValue(event.data.ieeeAddr, args.key);
}
},
];
return { onEvent, options: args.option ? [args.option] : [], isModernExtend: true };
}

Logs with the broken (basically untouched) function:

[2025-10-26 05:05:04] info:     zhc:lixee: Entering local poll function (broken)
[2025-10-26 05:05:04] info:     z2m: Loaded external converter 'lixee.js'.
[2025-10-26 05:05:04] info:     z2m: Loaded external converter 'lixee.js'.
[2025-10-26 05:05:04] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 5
[2025-10-26 05:05:09] info:     zhc:lixee: Running poll with interval 5
[2025-10-26 05:05:19] info:     zhc:lixee: Running poll with interval 5
[2025-10-26 05:05:22] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 4
[2025-10-26 05:05:22] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 4
[2025-10-26 05:05:26] info:     zhc:lixee: Running poll with interval 4
[2025-10-26 05:05:29] info:     zhc:lixee: Running poll with interval 5
[2025-10-26 05:05:37] info:     zhc:lixee: Running poll with interval 4
[2025-10-26 05:05:43] info:     zhc:lixee: Running poll with interval 5

Logs with the fixed function:

[2025-10-26 05:08:46] info:     zhc:lixee: Entering local poll function (fixed)                                                                                                                                    
[2025-10-26 05:08:46] info:     z2m: Loaded external converter 'lixee.js'.                                                                                                                                         
[2025-10-26 05:08:46] info:     z2m: Loaded external converter 'lixee.js'.                                                                                                                                         
[2025-10-26 05:08:46] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 6                                                                                                      
[2025-10-26 05:08:50] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 6                                                                                                      
[2025-10-26 05:08:56] info:     zhc:lixee: Running poll with interval 6                                                                                                                                            
[2025-10-26 05:08:58] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 5                                                                                                      
[2025-10-26 05:09:03] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:08] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:11] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 4                                                                                                      
[2025-10-26 05:09:15] info:     zhc:lixee: Running poll with interval 4                                                                                                                                            
[2025-10-26 05:09:19] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 5                                                                                                      
[2025-10-26 05:09:24] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:29] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:34] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:39] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:44] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:49] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:54] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:09:59] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:10:04] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:10:10] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            
[2025-10-26 05:10:15] info:     zhc:lixee: Running poll with interval 5                                                                                                                                            

I still don't understand why I have trouble reproducing the problem with my poll function defined in my converter.

EDIT: I also don't understand why at an interval of is sometimes repeated.

[Nerivec]

The lixee is probably not the best test subject for this, the converter being what it is...
Do you have another device to test this with maybe?

About the duplicated Polling..., check the full logs, you'd have to get duplicate deviceOptionsChanged events for this to happen (unless there's a flaw somewhere).

[sbraz]

About the duplicated Polling..., check the full logs, you'd have to get duplicate deviceOptionsChanged events for this to happen (unless there's a flaw somewhere).

That's the Changed config log, right? Only one occurrence of it:

[2025-10-26 13:56:31] info:     zhc:lixee: Entering local poll function (fixed)
[2025-10-26 13:56:31] info:     z2m: Loaded external converter 'lixee.js'.
[2025-10-26 13:56:31] info:     z2m: Loaded external converter 'lixee.js'.
[2025-10-26 13:56:31] info:     z2m: Loaded external converter 'nodon.js'.
[2025-10-26 13:56:31] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 11
[2025-10-26 13:56:39] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:56:39] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 12
[2025-10-26 13:56:39] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 12
[2025-10-26 13:56:48] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:56:49] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:56:51] info:     zhc:lixee: Running poll with interval 12

I can reproduce rather easily, it occurs only on the first poll interval change, not for subsequent changes (at least I don't think so):

[2025-10-26 13:59:29] info:     zhc:lixee: Entering local poll function (fixed)
[2025-10-26 13:59:29] info:     z2m: Loaded external converter 'lixee.js'.
[2025-10-26 13:59:29] info:     z2m: Loaded external converter 'lixee.js'.
[2025-10-26 13:59:29] info:     z2m: Loaded external converter 'nodon.js'.
[2025-10-26 13:59:29] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 7
[2025-10-26 13:59:32] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:59:32] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 5
[2025-10-26 13:59:32] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 5
[2025-10-26 13:59:35] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:59:35] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 4
[2025-10-26 13:59:39] info:     zhc:lixee: Running poll with interval 4
[2025-10-26 13:59:42] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:59:42] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 3
[2025-10-26 13:59:44] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:59:44] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 4
[2025-10-26 13:59:46] info:     z2m: Changed config for device 0xaddress
[2025-10-26 13:59:46] debug:    zhc:lixee: Polling 'measurement' for '0xaddress' at an interval of 5

Do you have another device to test this with maybe?

I don't think so, do any of these use polling?

IKEA E2206
IKEA E22x4
IKEA LED2109G6
IKEA LED2111G6
IKEA LED2201G8
Legrand 412171
LiXee ZLinky_TIC
Lidl HG07834B/HG09155B/HG08131B
NodOn SEM-4-1-00
NodOn SIN-4-FP-21
Philips 8719514491229
SONOFF SNZB-01P
SONOFF SNZB-02D
SONOFF SNZB-02P
SONOFF SNZB-02WD
SONOFF SWV
SONOFF ZBDongle-E
Third Reality 3RSM0147Z

In any case, after adding the condition you suggested, I never had duplicate poll calls.

[Nerivec]

it occurs only on the first poll interval change, not for subsequent changes

Ah, I think the onEvent code calls start on first exec. That must be it start+deviceOptionsChanged => two Polling....
@Koenkk can you check that one, you're more familiar with the onEvent logic. Seems it's making unnecessary calls in a case like this one, it's probably not the only one.

[Koenkk]

I cannot find where a start would be immediately followed by a deviceOptionsChanged. Could you log the whole event on this line?

[Nerivec]

@Koenkk here?
https://github.com/Koenkk/zigbee2mqtt/blob/961265ad5eb0a00a34192d68c2f88f5dad7bfac5/lib/extension/onEvent.ts#L74

[sbraz]

I cannot find where a start would be immediately followed by a deviceOptionsChanged. Could you log the whole event on this line?

https://bpa.st/raw/2GJGQ

With the following poll function:

Details

```js function poll_fixed(args) { logger_1.logger.info(`Entering local poll function (fixed)`, NS); const optionKey = args.optionKey ?? `${args.key}_poll_interval`; const onEvent = [ (event) => { if (event.type === "start" || (event.type === "deviceOptionsChanged" && event.data.from[optionKey] !== event.data.to[optionKey])) { logger_1.logger.info(`Start event: ${JSON.stringify(event)}`, NS); let seconds = args.defaultIntervalSeconds; if (args.option) { seconds = (0, utils_1.toNumber)(event.data.options[optionKey] ?? args.defaultIntervalSeconds, optionKey); } clearTimeout(globalStore.getValue(event.data.device.ieeeAddr, args.key)); if (seconds &lt;= 0) { logger_1.logger.debug(`Not polling '${args.key}' for '${event.data.device.ieeeAddr}' since poll interval is <= 0 (got ${seconds})`, NS); } else { logger_1.logger.debug(`Polling '${args.key}' for '${event.data.device.ieeeAddr}' at an interval of ${seconds}`, NS); const setTimer = () =&gt; { const timer = setTimeout(async () =&gt; { try { await args.poll(event.data.device, event.data.options); } catch (error) { logger_1.logger.debug(`Poll of '${event.data.device.ieeeAddr}' failed (${error})`, NS); } if (globalStore.getValue(event.data.device.ieeeAddr, args.key) === timer) { setTimer(); } }, seconds * 1000); globalStore.putValue(event.data.device.ieeeAddr, args.key, timer); }; setTimer(); } } else if (event.type === "stop") { clearTimeout(globalStore.getValue(event.data.ieeeAddr, args.key)); globalStore.clearValue(event.data.ieeeAddr, args.key); } }, ]; return { onEvent, options: args.option ? [args.option] : [], isModernExtend: true }; } ```

@Koenkk @Nerivec please let me know when I can delete the paste.

That's the only difference between both events that fire when I change the interval for the first time:

--- /dev/fd/63  2025-10-26 22:45:18.684135421 +0100
+++ /dev/fd/62  2025-10-26 22:45:18.685135423 +0100
@@ -340,6 +340,15 @@
         "configured": 332242049
       }
     },
+    "from": {
+      "energy_phase": "single_phase",
+      "linky_mode": "standard",
+      "measurement_poll_chunk": 2,
+      "measurement_poll_interval": 58,
+      "production": "false",
+      "tarif": "Standard - TEMPO",
+      "tic_command_whitelist": "MSG1,MSG2,LTARF,EAST,EASF01,EASF02,EASF03,EASF04,EASF05,EASF06,EASF07,EASF08,EASF09,EASF10,IRMS1,URMS1,PREF,PCOUP,SINSTI,CCASN,CCASN-1,SINSTS,SMAXN,SMAXN-1"
+    },
     "options": {
       "ID": "0x00158d000638f47a",
       "energy_phase": "single_phase",
@@ -402,7 +411,16 @@
         "latest_version": 17,
         "state": "idle"
       }
+    },
+    "to": {
+      "energy_phase": "single_phase",
+      "linky_mode": "standard",
+      "measurement_poll_chunk": 2,
+      "measurement_poll_interval": 57,
+      "production": "false",
+      "tarif": "Standard - TEMPO",
+      "tic_command_whitelist": "MSG1,MSG2,LTARF,EAST,EASF01,EASF02,EASF03,EASF04,EASF05,EASF06,EASF07,EASF08,EASF09,EASF10,IRMS1,URMS1,PREF,PCOUP,SINSTI,CCASN,CCASN-1,SINSTS,SMAXN,SMAXN-1"
     }
   },
-  "type": "start"
+  "type": "deviceOptionsChanged"
 }

[Koenkk]

@Koenkk here? https://github.com/Koenkk/zigbee2mqtt/blob/961265ad5eb0a00a34192d68c2f88f5dad7bfac5/lib/extension/onEvent.ts#L74

Good catch, nasty bug. Fixed it in Koenkk/zigbee2mqtt#29322

[Koenkk]

@sbraz Koenkk/zigbee2mqtt#29322 is merged now, can you check if it works?

Changes will be available in the dev branch in a few hours from now and in the next release which is every 1st of the month.