I have ~10 Zigbee battery motion sensors (Iris 3326-L), and every once in a while one of them stops reporting. I monitor last-report date/times via a rule and restart the bundle via a shell script. It works, but it’s pretty heavy-handed.
I’m trying to find a way to recover individual Zigbee (or Z-Wave) sensors that become unresponsive without nuking the whole mesh, but so far haven’t found an approach.
Has anyone cracked that code yet? Is it even possible?
Restarting the binding really should not bring the device back online - it might say it’s online, but given this is a battery device, and most battery devices will not be listening, then it really shouldn’t make any difference.
The binding configures devices to send reports periodically, and if it doesn’t receive 2 reports that it expects in a row, it gets marked offline. When a report comes in, it will be marked online again…
It would be interesting to understand what you are monitoring, and what the debug logs shows is happening for the device to understand what is happening. I think it is necessary to know what problem you’re actually trying to “crack”.
Interesting, thanks for the additional information. I hadn’t considered that the sensor could be happily broadcasting away and the problem was elsewhere in the chain.
I don’t know for sure that they’re marked offline, I’ll check next time it happens. I noticed it when started graphing room temperatures over time. So when I say offline I mean the sensor is no longer updating its temperature value - it “flatlines” on the graph.
I’ve turned on debug logging for the Zigbee binding and another “last-update” item that monitors battery level from the same sensors. I will report back when it happens again and I have some more debug data.
events.log generally go back a fair way, you should find older generations in /userdata/logs
Note that if your Item gets updated to UNDEF by binding (e.g. detecting some error) or remains at NULL for some time after a reboot (failure to initially update) these are ignored and not recorded by persistence service.
I see that now, thank you.
Some more context. It looks like the last time was during a restart/reboot (not sure which). It looks like in this case there was an error on initialization.
The sensor in question here is: 000D6F000E260024
The item is: nLiving_Room_Temp
openhab.log:
Blockquote
2020-01-17 15:18:36.262 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000D6F000E260024 : Starting ZigBee device discovery
2020-01-17 15:19:35.002 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000D6F000E260024 : Starting ZigBee device discovery
2020-01-17 15:40:31.769 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6F000E260024 : Exception creating channels
2020-01-17 15:41:52.877 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6F000E260024 : Exception creating channels
2020-01-17 15:42:51.095 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - 000D6F000E260024 : Exception creating channels
events.log:
Blockquote
events.log.4:2020-01-17 15:32:06.273 [vent.ItemStateChangedEvent] - nLiving_Room_Temp changed from 52.934 °F to 52.97 °F
events.log.4:2020-01-17 15:32:06.275 [GroupItemStateChangedEvent] - avg_room_temps changed from 55.112 to 55.118 through nLiving_Room_Temp
events.log.4:2020-01-17 15:18:29.237 [vent.ItemStateChangedEvent] - nLiving_Room_Temp changed from NULL to 52.97 °F
events.log.4:2020-01-17 15:18:29.335 [GroupItemStateChangedEvent] - avg_room_temps changed from 55.622 to 55.169 through nLiving_Room_Temp
events.log.5:2020-01-18 06:49:01.512 [temChannelLinkRemovedEvent] - Link ‘nLiving_Room_Temp => zigbee:device:7812aab4:000d6f000e260024:000D6F000E260024_1_temperature’ has been removed.
events.log.5:2020-01-18 06:50:45.991 [vent.ItemStateChangedEvent] - nLiving_Room_Temp changed from NULL to 52.97 °F
events.log.5:2020-01-18 06:53:22.784 [GroupItemStateChangedEvent] - avg_room_temps changed from 56.066 to 56.462 through nLiving_Room_Temp
events.log.5:2020-01-18 06:53:22.786 [vent.ItemStateChangedEvent] - nLiving_Room_Temp changed from 52.97 °F to 55.346 °F
It’s hard to know what is happening here - the events log doesn’t really mean a lot and I’d really need to see a debug log to understand what’s going on.
Use the openhabian-config tool and set the rules to load after OH has started and see if that helps.
I’ve got debug logs on now, just waiting for it to happen again…
Well, a bit more information.
Grep’d log from a restart where one of the sensors didn’t come up is below. The reason I restarted is because the sensor wasn’t sending update. I was trying to separate out the zigbee log into a separate file when that happened, and I (of course) didn’t capture that event.
The restart that generated this log didn’t knock the sensor free - meaning it’s still not reporting. It is alive and sensing movement, though, per the LED indicator on the sensor itself.
27-Jan-2020 20:45:50.392 [INFO ] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00057B8CDE: Starting ZigBee device discovery
27-Jan-2020 20:49:28.681 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Dynamically created 7 channels
27-Jan-2020 20:49:28.684 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Device initialization will be skipped as the device is already initialized
27-Jan-2020 20:49:28.687 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_motionintrusion
27-Jan-2020 20:49:52.705 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_tamper
27-Jan-2020 20:50:16.715 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_motionpresence
27-Jan-2020 20:50:28.720 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for system:low-battery
27-Jan-2020 20:50:52.725 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Channel initialisation complete
27-Jan-2020 20:51:04.733 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Error getting binding table
27-Jan-2020 20:51:04.738 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Polling initialised at 7389421ms
27-Jan-2020 20:51:04.740 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Done initialising ZigBee Thing handler
27-Jan-2020 20:51:05.195 [DEBUG] [rg.openhab.binding.zigbee.internal.ZigBeeDataStore] - 000D6F00057B8CDE: ZigBee saving network state complete.
The sensor state persisted through openhab restarts. After deleting and re-discovering it, the common issue seems to be “Error getting binding table”.
28-Jan-2020 10:47:12.657 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00057B8CDE: Discovery: Starting discovery for existing device
28-Jan-2020 10:47:12.669 [INFO ] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00057B8CDE: Starting ZigBee device discovery
28-Jan-2020 10:47:12.671 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00057B8CDE: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:7812aab4
28-Jan-2020 10:47:12.690 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery start
28-Jan-2020 10:47:12.692 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery using basic cluster on endpoint 8556/1
28-Jan-2020 10:47:36.700 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: Application version failed
28-Jan-2020 10:47:36.701 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery using OTA cluster on endpoint 8556/1
28-Jan-2020 10:47:36.703 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x104e, modelId=3326-L, zigbee_networkaddress=34134, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=2, zigbee_datecode=����������������, zigbee_zclversion=1, vendor=CentraLite, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x11015310}
28-Jan-2020 10:47:36.704 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00057B8CDE: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:7812aab4, label 'CentraLite 3326-L'
28-Jan-2020 10:47:37.034 [DEBUG] [rg.openhab.binding.zigbee.internal.ZigBeeDataStore] - 000D6F00057B8CDE: ZigBee saving network state complete.
28-Jan-2020 10:47:37.281 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing ZigBee thing handler zigbee:device:7812aab4:000d6f00057b8cde
28-Jan-2020 10:47:37.287 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Coordinator status changed to ONLINE.
28-Jan-2020 10:47:37.289 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Coordinator is ONLINE. Starting device initialisation.
28-Jan-2020 10:47:37.306 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Start initialising ZigBee Thing handler
28-Jan-2020 10:47:37.312 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery start
28-Jan-2020 10:47:37.313 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery using basic cluster on endpoint 8556/1
28-Jan-2020 10:48:01.317 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: Application version failed
28-Jan-2020 10:48:01.319 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery using OTA cluster on endpoint 8556/1
28-Jan-2020 10:48:01.321 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00057B8CDE: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x104e, modelId=3326-L, zigbee_networkaddress=34134, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=2, zigbee_datecode=����������������, zigbee_zclversion=1, vendor=CentraLite, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x11015310}
28-Jan-2020 10:48:01.323 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Checking endpoint 1 channels
28-Jan-2020 10:48:13.327 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.335 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.339 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.342 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.352 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.355 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.362 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.365 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.369 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: IAS zone type MOTION_SENSOR
28-Jan-2020 10:48:13.374 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Checking endpoint 2 channels
28-Jan-2020 10:48:49.394 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Dynamically created 7 channels
28-Jan-2020 10:48:49.408 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Updating thing definition as channels have changed from [] to [zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_intrusion, zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_temperature, zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_tamper, zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_batteryalarm, zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_motion, zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_iaslowbattery, zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_batteryvoltage]
28-Jan-2020 10:48:49.436 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing device
28-Jan-2020 10:48:49.441 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_intrusion with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterIasMotionIntrusion@1e775c3
28-Jan-2020 10:48:49.443 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_motionintrusion
28-Jan-2020 10:49:01.448 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_temperature with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterTemperature@1501210
28-Jan-2020 10:49:13.452 [DEBUG] [gbee.internal.converter.ZigBeeConverterTemperature] - 000D6F00057B8CDE: Failed to bind temperature measurement cluster
28-Jan-2020 10:49:13.454 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_tamper with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterIasTamper@16e237
28-Jan-2020 10:49:13.455 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_tamper
28-Jan-2020 10:49:25.458 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_batteryalarm with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryAlarm@1b38e4a
28-Jan-2020 10:49:25.460 [DEBUG] [bee.internal.converter.ZigBeeConverterBatteryAlarm] - 000D6F00057B8CDE: Initialising device battery alarm converter
28-Jan-2020 10:49:37.464 [INFO ] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_batteryalarm failed to initialise device
28-Jan-2020 10:49:37.466 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_motion with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterIasMotionPresence@17caf12
28-Jan-2020 10:49:37.467 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_motionpresence
28-Jan-2020 10:49:49.471 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_iaslowbattery with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterIasLowBattery@d3e8bf
28-Jan-2020 10:49:49.473 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for system:low-battery
28-Jan-2020 10:50:01.477 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Initializing channel zigbee:device:7812aab4:000d6f00057b8cde:000D6F00057B8CDE_1_batteryvoltage with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterBatteryVoltage@127ad08
28-Jan-2020 10:50:01.480 [DEBUG] [e.internal.converter.ZigBeeConverterBatteryVoltage] - 000D6F00057B8CDE: Initialising device battery voltage converter
28-Jan-2020 10:50:13.485 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_motionintrusion
28-Jan-2020 10:50:37.502 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_tamper
28-Jan-2020 10:51:01.509 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for zigbee:ias_motionpresence
28-Jan-2020 10:51:13.515 [DEBUG] [nding.zigbee.internal.converter.ZigBeeConverterIas] - 000D6F00057B8CDE: Initialising device IAS Zone cluster for system:low-battery
28-Jan-2020 10:51:37.521 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Channel initialisation complete
28-Jan-2020 10:51:49.528 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Error getting binding table
28-Jan-2020 10:51:49.533 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Polling initialised at 7425207ms
28-Jan-2020 10:51:49.536 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00057B8CDE: Done initialising ZigBee Thing handler
28-Jan-2020 10:51:50.105 [DEBUG] [rg.openhab.binding.zigbee.internal.ZigBeeDataStore] - 000D6F00057B8CDE: ZigBee saving network state complete.
Caught it!
The device in question is: zigbee:device:7812aab4:000d6f001099df94:000D6F001099DF94
Debug log file is shared here.
Thanks.
It looks like for some reason the binding reinitialised and I’ve found a bug in the temperature converter that was causing an exception during the startup.
I’ve created a PR to fix that - let’s see if that helps -:
Brilliant - thank you!
I’ll report back if I see it again.
Hey Chris, when will this fix be released, i’m still having the same problem with my osram motion sensor since i updated to 2.5.1? Do i need to reinstall the binding? Thanks for fixing that. Hope my lights will turn on on their own again in the future. ^^
I’m afraid I don’t know what the release schedule is - sorry.
You will need to use the snapshot version - 2.5.2-SNAPSHOT.