Open TheNetStriker opened 3 years ago
@TheNetStriker unfortunately this issue wasn;t picked up earlier. As many changed to homy, openHAB and the binding have been committed, i thinkg it would be wise if you can confirm this issue is still occuring on openHAB 4.1.x
I've just tested this in OpenHab 4.1 and regarding the logs the channels still don't always all get unsubscribed. Here is a log where I renamed a channel 3 times:
2023-12-31 13:18:43.734 [DEBUG] [e.internal.handler.HomieThingHandler] - About to stop Homie device rollershuttercontroller01
2023-12-31 13:18:43.735 [DEBUG] [e.internal.handler.HomieThingHandler] - About to initialize Homie device rollershuttercontroller01
2023-12-31 13:18:43.736 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#calibrationstate from topic: homie/rollershuttercontroller01/rollershutter1/calibrationstate
2023-12-31 13:18:43.737 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#moving from topic: homie/rollershuttercontroller01/rollershutter1/moving
2023-12-31 13:18:43.737 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#position from topic: homie/rollershuttercontroller01/rollershutter1/position
2023-12-31 13:18:43.737 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#calibrationstate from topic: homie/rollershuttercontroller01/rollershutter2/calibrationstate
2023-12-31 13:18:43.739 [DEBUG] [e.internal.handler.HomieThingHandler] - About to start Homie device rollershuttercontroller01
2023-12-31 13:18:43.784 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#calibrationstate to topic: homie/rollershuttercontroller01/rollershutter1/calibrationstate
2023-12-31 13:18:43.784 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#moving to topic: homie/rollershuttercontroller01/rollershutter1/moving
2023-12-31 13:18:43.785 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#position to topic: homie/rollershuttercontroller01/rollershutter1/position
2023-12-31 13:18:43.785 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#calibrationstate to topic: homie/rollershuttercontroller01/rollershutter2/calibrationstate
2023-12-31 13:18:43.785 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#moving to topic: homie/rollershuttercontroller01/rollershutter2/moving
2023-12-31 13:18:43.785 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#position to topic: homie/rollershuttercontroller01/rollershutter2/position
2023-12-31 13:18:43.786 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#calibrationselection to topic: homie/rollershuttercontroller01/system/calibrationselection
2023-12-31 13:18:43.786 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#log to topic: homie/rollershuttercontroller01/system/log
2023-12-31 13:18:43.786 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#reset to topic: homie/rollershuttercontroller01/system/reset
2023-12-31 13:18:43.787 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#rssi to topic: homie/rollershuttercontroller01/system/rssi
2023-12-31 13:18:43.787 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#temperature to topic: homie/rollershuttercontroller01/system/temperature
2023-12-31 13:18:43.986 [DEBUG] [e.internal.handler.HomieThingHandler] - Homie device rollershuttercontroller01 fully attached (start)
2023-12-31 13:18:44.254 [DEBUG] [e.internal.handler.HomieThingHandler] - Homie device rollershuttercontroller01 fully attached (accept)
2023-12-31 13:19:34.343 [DEBUG] [e.internal.handler.HomieThingHandler] - About to initialize Homie device rollershuttercontroller01
2023-12-31 13:19:34.347 [DEBUG] [e.internal.handler.HomieThingHandler] - About to start Homie device rollershuttercontroller01
2023-12-31 13:19:34.349 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#calibrationstate from topic: homie/rollershuttercontroller01/rollershutter1/calibrationstate
2023-12-31 13:19:34.349 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#moving from topic: homie/rollershuttercontroller01/rollershutter1/moving
2023-12-31 13:19:34.349 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#position from topic: homie/rollershuttercontroller01/rollershutter1/position
2023-12-31 13:19:34.350 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#calibrationstate from topic: homie/rollershuttercontroller01/rollershutter2/calibrationstate
2023-12-31 13:19:34.350 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#moving from topic: homie/rollershuttercontroller01/rollershutter2/moving
2023-12-31 13:19:34.350 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#position from topic: homie/rollershuttercontroller01/rollershutter2/position
2023-12-31 13:19:34.351 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#calibrationselection from topic: homie/rollershuttercontroller01/system/calibrationselection
2023-12-31 13:19:34.351 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#log from topic: homie/rollershuttercontroller01/system/log
2023-12-31 13:19:34.352 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#reset from topic: homie/rollershuttercontroller01/system/reset
2023-12-31 13:19:34.353 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#rssi from topic: homie/rollershuttercontroller01/system/rssi
2023-12-31 13:19:34.353 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Unsubscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#temperature from topic: homie/rollershuttercontroller01/system/temperature
2023-12-31 13:19:34.396 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#calibrationstate to topic: homie/rollershuttercontroller01/rollershutter1/calibrationstate
2023-12-31 13:19:34.397 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#moving to topic: homie/rollershuttercontroller01/rollershutter1/moving
2023-12-31 13:19:34.398 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#position to topic: homie/rollershuttercontroller01/rollershutter1/position
2023-12-31 13:19:34.398 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#calibrationstate to topic: homie/rollershuttercontroller01/rollershutter2/calibrationstate
2023-12-31 13:19:34.399 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#moving to topic: homie/rollershuttercontroller01/rollershutter2/moving
2023-12-31 13:19:34.399 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#position to topic: homie/rollershuttercontroller01/rollershutter2/position
2023-12-31 13:19:34.400 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#calibrationselection to topic: homie/rollershuttercontroller01/system/calibrationselection
2023-12-31 13:19:34.400 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#log to topic: homie/rollershuttercontroller01/system/log
2023-12-31 13:19:34.401 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#reset to topic: homie/rollershuttercontroller01/system/reset
2023-12-31 13:19:34.401 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#rssi to topic: homie/rollershuttercontroller01/system/rssi
2023-12-31 13:19:34.402 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#temperature to topic: homie/rollershuttercontroller01/system/temperature
2023-12-31 13:19:34.600 [DEBUG] [e.internal.handler.HomieThingHandler] - Homie device rollershuttercontroller01 fully attached (start)
2023-12-31 13:19:34.857 [DEBUG] [e.internal.handler.HomieThingHandler] - Homie device rollershuttercontroller01 fully attached (accept)
2023-12-31 13:20:26.499 [DEBUG] [e.internal.handler.HomieThingHandler] - About to stop Homie device rollershuttercontroller01
2023-12-31 13:20:26.500 [DEBUG] [e.internal.handler.HomieThingHandler] - About to initialize Homie device rollershuttercontroller01
2023-12-31 13:20:26.504 [DEBUG] [e.internal.handler.HomieThingHandler] - About to start Homie device rollershuttercontroller01
2023-12-31 13:20:26.548 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#calibrationstate to topic: homie/rollershuttercontroller01/rollershutter1/calibrationstate
2023-12-31 13:20:26.548 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#moving to topic: homie/rollershuttercontroller01/rollershutter1/moving
2023-12-31 13:20:26.548 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter1#position to topic: homie/rollershuttercontroller01/rollershutter1/position
2023-12-31 13:20:26.549 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#calibrationstate to topic: homie/rollershuttercontroller01/rollershutter2/calibrationstate
2023-12-31 13:20:26.549 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#moving to topic: homie/rollershuttercontroller01/rollershutter2/moving
2023-12-31 13:20:26.549 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:rollershutter2#position to topic: homie/rollershuttercontroller01/rollershutter2/position
2023-12-31 13:20:26.549 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#calibrationselection to topic: homie/rollershuttercontroller01/system/calibrationselection
2023-12-31 13:20:26.549 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#log to topic: homie/rollershuttercontroller01/system/log
2023-12-31 13:20:26.550 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#reset to topic: homie/rollershuttercontroller01/system/reset
2023-12-31 13:20:26.550 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#rssi to topic: homie/rollershuttercontroller01/system/rssi
2023-12-31 13:20:26.551 [DEBUG] [ab.binding.mqtt.generic.ChannelState] - Subscribed channel mqtt:homie300:4ce1d806:rollershuttercontroller01:system#temperature to topic: homie/rollershuttercontroller01/system/temperature
2023-12-31 13:20:26.750 [DEBUG] [e.internal.handler.HomieThingHandler] - Homie device rollershuttercontroller01 fully attached (start)
2023-12-31 13:20:27.014 [DEBUG] [e.internal.handler.HomieThingHandler] - Homie device rollershuttercontroller01 fully attached (accept)
Every rename attempt has different channels that are unsubscribed. On the first attempt not everything was unsubscribed. The second attempt worked correctly and on the last attempt nothing was unsubscribed.
This doesn't look consistent. The last block has
About to stop Homie device rollershuttercontroller01
while the second block is missing thas line. No lines are accidently missed?
This doesn't look consistent. The last block has
About to stop Homie device rollershuttercontroller01
while the second block is missing thas line. No lines are accidently missed?
I've removed some lines in between that had nothing to do with the restart. I guess I accidentally removed this line too.
I'll try to take a look at this sometime soon. I'm about out of time during winter break though, so it might be a few weeks, and I've got one more MQTT-related commit to finish up first.
Expected Behavior
When changing channel settings in a Homie thing, all MQTT topics should be unsubscribed and then re-subscribed.
Current Behavior
The Homie MQTT binding only unsubscribes some of the MQTT topics. (Seems to be random which one's do get unsubscribed or not) This behaviour results in multiple rule events for a single MQTT message after the change. Only a restart of OpenHab solves this problem.
Steps to Reproduce (for Bugs)
Enable debug logging for MQTT binding and change e.g. one of the channel names in a Homie thing in PaperUI.
Logs
Here are my MQTT logs after changing one channel name:
And here are the Homie topics of this device:
Your Environment
OpenHabian on Raspberry Pi 4 with OpenHab 2.5.