OH3 erratic zwave (40 nodes) behaviour upon migration from 2.5

rdslw · October 19, 2022, 4:54pm

I’m kind of stumbled and need some guidance/suggestion re problem I encountered.

I help to migrate medium sized (1000+ items) OH setup, from 2.5 to 3.3. Setup is using both KNX (mainly) and zwave (only 40 nodes). Upon migration, zwave most of the time works, however I’m constantly observing strange patterns (logs and details below) of errors regarding zwave things & items:

zwave binding reports every days multiple “UFO” nodes with different ids
there is repeatedly pattern of repeated (10…20) withing 1 second of ‘received command’ with ‘predicted to became’ log entries for the very same zwave connected item
I’m seeing dozen (sic!) times a day situations, when value of some meter on a specific zwave device, jumps to different value and then within 1s, returns to the previous value.

All three things, looks for me like some kind of garbled content of zwave messages, or some error in higher (radio? binding?) layer, however I thought that securitykey and checksums are protecting from such messages reaching even zwave binding.

I did restart openhab. Did also clean cache/ & tmp/
Did not reboot hardware (rpi3b + aeotec stick on usb)

hardware is the same (2.5 and 3.3), all locations etc, not changed, added 2 new zwave devices during migration, while removed one. all this cases (1,2,3), happen multiple times every day, starting from the day of migration from 2.5 to 3.3. NB, a lot of zwave messages are passed to OH properly and correctly, maybe 2% result in such cases as 1,2,3 i’m looking to solve.

Suggestions highly welcome

example of 1:

2022-10-19 17:10:48.802 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 25: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:52.555 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:52.644 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:52.657 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:52.841 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.245 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.355 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.439 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.511 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.542 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.555 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.636 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:30:53.694 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 139: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:48.637 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.054 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.084 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.244 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.351 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.550 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.601 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.687 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.699 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.767 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:49.965 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:50:50.107 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 26: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:51:34.959 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 136: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:51:35.178 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 136: Not initialized (ie node unknown), ignoring message.
2022-10-19 17:51:35.192 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] NODE 136: Not initialized (ie node unknown), ignoring message.

example of case 2:

2022-10-19 18:41:31.350 Item 'zwaHACKsensorUniMotion' changed from ON to OFF
2022-10-19 18:44:52.450 Item 'zwaHACKsensorUniMotion' changed from OFF to ON (this action causes ONE invocation of rule to be send to enable zwaHACKpowerpDesklamp)
2022-10-19 18:44:52.465 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.467 Item 'zwaHACKpowerpDesklamp' predicted to become ON
2022-10-19 18:44:52.520 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.522 Item 'zwaHACKpowerpDesklamp' predicted to become ON
2022-10-19 18:44:52.541 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.542 Item 'zwaHACKpowerpDesklamp' predicted to become ON
2022-10-19 18:44:52.574 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.575 Item 'zwaHACKpowerpDesklamp' predicted to become ON
2022-10-19 18:44:52.623 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.624 Item 'zwaHACKpowerpDesklamp' predicted to become ON
2022-10-19 18:44:52.665 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.667 Item 'zwaHACKpowerpDesklamp' predicted to become ON
2022-10-19 18:44:52.709 Item 'zwaHACKpowerpDesklamp' received command ON
2022-10-19 18:44:52.711 Item 'zwaHACKpowerpDesklamp' predicted to become ON

example of case 3:

2022-10-19 15:48:27.446 Item 'zwaLIBRlidimmReadinglampEnergy' changed from 3.53 to 240.838
2022-10-19 15:48:38.010 Item 'zwaLIBRlidimmReadinglampEnergy' changed from 240.838 to 3.53

chris · October 19, 2022, 6:11pm

There are two main causes of this sort of thing that I’ve seen in the past. Firstly, a device may have had its memory corrupted and might need to be reset (ie powered down and back on again). Secondly, ZWave is actually not very tolerant to errors, so data corruption “over the air” (ie when data is transmitted through RF) doesn’t, by default, have good error detection. This can mean that corrupt frames get received.

Given here there are a lot of messages allegedly from the same node in short time, I would guess that the problem is one or more nodes need to be reset. I’m not completely sure how to find which one other than trial and error. You could look to see if some nodes that should be reporting are not reporting - that might indicate an issue.

Or of course it could be something different …

rdslw · October 19, 2022, 6:32pm

Thanks @chris for reply.

as to the failed node scenario, and example 3, it happens to at least 6+ nodes (if not more, because I dont always observe it), and to totally random channels of that nodes. It all started at the same time (few days ago upon migration), so I’m rather not betting on one device being broken, too much coincidence

Unless it is aeotec, which might be possible.

The case 3 and 2 from my post might be most easy to debug, and I’m inclined to find the root cause, as currently event if it happens dozen times a day it almost makes impossible to use any warning/counting etc usage of the devices (all kind of fake alarms of temperature, amperage, etc.)

Before going into deeper looking, two questions:

would removing all xml file (/var/lib/openhab/zwave) help?
hardware reset of aeotec ?

Case 2 happens a lot under the hood, just from last hour, grep on zwave_debug.log on ‘Updating channel’ shows me:

d19 20:24:00.855 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:00.927 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:00.976 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:01.124 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:01.222 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:01.376 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:01.443 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:01.513 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:01.638 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_voltage to 0 [DecimalType]
d19 20:24:02.531 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.645 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.656 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.729 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.783 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.849 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.878 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:02.965 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:03.025 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:03.124 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:03.185 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:03.249 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:24:03.463 NODE 36: Updating channel state zwave:device:czaroaeotec:node36:meter_current to 0 [DecimalType]
d19 20:25:23.662 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:23.942 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.112 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.189 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.307 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.324 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.529 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.592 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.663 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.705 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.713 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:24.917 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:25.044 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:26.438 NODE 4: Updating channel state zwave:device:czaroaeotec:node4:meter_kwh to 31.27 [DecimalType]
d19 20:25:44.245 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:44.312 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:44.578 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:44.690 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:44.705 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:44.742 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:44.882 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.043 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.048 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.062 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.171 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.198 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.298 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:25:45.418 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:sensor_power to 0.8 [DecimalType]
d19 20:28:38.711 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:38.899 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:38.965 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:38.996 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.049 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.062 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.215 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.249 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.374 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.605 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:39.638 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_kwh to 3.53 [DecimalType]
d19 20:28:44.821 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:44.892 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:44.922 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.165 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.214 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.223 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.231 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.426 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.484 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:45.628 NODE 3: Updating channel state zwave:device:czaroaeotec:node3:meter_watts to 0 [DecimalType]
d19 20:28:58.566 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:58.876 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:58.887 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:58.894 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:58.950 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:59.093 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:59.162 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:59.227 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:28:59.342 NODE 37: Updating channel state zwave:device:czaroaeotec:node37:meter_kwh to 328.14 [DecimalType]
d19 20:29:23.781 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:23.857 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:23.876 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:23.990 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.055 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.101 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.133 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.237 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.311 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.389 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:24.481 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_kwh to 23.94 [DecimalType]
d19 20:29:27.118 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.126 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.185 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.345 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.390 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.427 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.509 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.564 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.578 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.639 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.670 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.704 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.763 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:27.857 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:28.072 NODE 2: Updating channel state zwave:device:czaroaeotec:node2:meter_current to 0.04 [DecimalType]
d19 20:29:43.405 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.500 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.526 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.607 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.697 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.742 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.800 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.845 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.893 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:29:43.944 NODE 40: Updating channel state zwave:device:czaroaeotec:node40:sensor_power to 22 [DecimalType]
d19 20:30:03.286 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.321 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.355 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.374 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.438 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.449 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.533 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.589 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.629 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.715 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.750 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.771 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:03.816 NODE 15: Updating channel state zwave:device:czaroaeotec:node15:meter_kwh to 21.88 [DecimalType]
d19 20:30:06.678 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:06.741 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:06.750 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:06.825 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:06.942 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:06.984 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:07.053 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:07.148 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:07.214 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]
d19 20:30:07.344 NODE 8: Updating channel state zwave:device:czaroaeotec:node8:sensor_power to 66.6 [DecimalType]

chris · October 19, 2022, 6:48pm

How do you know it is happening on 6 nodes? Do you mean that you see 6 “unknown” nodes in the logs? If that’s what you mean, that is not the same as saying that 6 “real” nodes have the problem. It could just be a single physical device that is sending corrupt data.

Again - it doesn’t mean that there are necessarily multiple devices with the problem. A device can easily send a message with an invalid node ID.

Note also that you need to consider that the root cause could have been nodes receiving a corrupt message - ie multiple devices could “crash” due to some sort of corrupt command received. So a few devices could be “infected” with a single source. Who knows.

No - this will make no difference.

You mean the dongle, or a device? As mentioned previously, resetting devices will likely help - resetting the controller will likely not, but it’s worth a try.

rdslw · October 19, 2022, 7:14pm

Here we were referring to case 3 from OP I suppose, so random switching value of a channel and reverting. I see this on multiple unrelated nodes and on different channels.

True, this might be one node spamming whole network with broken messages.

good to know. I thought (not sure if correct) that I’m kind immune to this, because I do not use direct commands between nodes and they’re not configured (apart if default enables it) for it, but will also take it into account.

Dongle being zwave stick connected to usb, which your binding uses to communicate with zwave network.

As for now:
I’ll try to remove two new nodes I added during migration, then hardware reset of dongle and server, and if that won’t help I’ll play with binary search over all zwave devices.

Would you have in the meantime any other suggestion, or question (logs etc), I’m happy to provide.

chris · October 19, 2022, 8:11pm

No really. The problem with this sort issue is that the logs are “lying” to us since the binding knows nothing about these nodes

apella12 · October 19, 2022, 8:25pm

I don’t have much besides offered by @chris except related to your “channel debug”. Check the config parameters on all your devices that report power (Watt, etc.) for selective rather than “timed” reporting (i.e. every several minutes). An “off” plug can get stray readings between 0 and 1 watt that will trigger a selective reports (ie report any change over 50%) at millisecond intervals. Also I have had Aeotec HEMs reset reporting parameters after a heal, so maybe something like that happened. To fix the parameter issue, I had to change from what was shown in the UI, then back to what was in the UI. It may be excessive traffic is contributing.

rdslw · October 20, 2022, 7:25pm

Update after a day. Changes:

Around 60% of nodes power-reseted
All battery nodes (around 7) turned off completly
aeotec dongle unplugged and plugged (which results in almost full OH restart on 3.3 :-/ )

Result:

case one, no longer happens: perfect
case two still happens on few (5) nodes, but channel update (happens with the same value, and around 200…500ms apart) is repeated only twice or (max) 3 times in one situation → so it is greatly reduced as previously it could be a 10+ repeats.
case 3 observed only once (which may be related to kind of broken device) so need more time to be sure

Hyphotesis:
What I’m observing (and trying to diagnose) are two different problems, with broken node (a) now eliminated, and second issue (b) of some kind routing/repeateing messages within zwave network.

I’m not sure how and when messages are repeated by zwave network, but I suppose here might lie one of the problems, especially connected with erratic heal and patchy coverage which is the case here.

Next steps: observe carefully if case 3 is limited to one device, and slowly enable battery operated nodes, as this might amplify problems.