Closed johny-mnemonic closed 1 year ago
JoDehli
commented
2 years ago Can you change the order of the scenes on one of the light controllers for testing. Change it to a scene where it can find a effect. Do you know what I mean?
I do not want to change something on the light controller as it runs ok for the most of the users. You can look on the light controllers itself maybe you can change something there to make it work better.
JoDehli
commented
2 years ago If you want you can send some pictures of one of your light controller configuration and how it is connected to the switch. I mean in loxone config. If I have time I can configure a light controller like you. I hate the light controller because it is to complex and not really good documented.
johny-mnemonic
commented
2 years ago I understand your viewpoint, but changing the order is not acceptable long term and as this happen only rarely, short term would still be at least few days, which would still be a big issue in two most used rooms in the house... The fact that this happens rarely also means it can find the effect most of the time, so I am not sure changing it to different scene would change anything.
So, I would rather find what is going on by debugging.
Maybe there is one important information missing in my OP. There are no logs at all in HA when there is no issue. These messages about sending plus and changeTo commands and messages from got_effect() function are only present, when this issue manifests.
And that makes complete sense as there is no reason for any command being send from HA to Loxone in the situation when the action originated from Loxone. The only thing that should happen in HA/PyLoxone is the update of the state in HA.
Which brings me to a question, where this is happening in PyLoxone. I mean which function(s) are taking care of catching the state change in Loxone and updating the state of the light entity in HA?
I would like to add logging there to see what is going on there. Why instead of just updating the state in HA it decides to call the got_effect() function which then starts sending commands back to Loxone.
I am lately seeing increased amount of timeouts when communicating with Miniserver in the HA log and starting HA has 50% chance of failing to start PyLoxone with errors about timeout or closed connection. So there is high chance the main driver is slow communication with the Miniserver, triggering some weird state in PyLoxone that wouldn't be triggered otherwise. I am also going to upgrade Loxone from v12 to v13 and check the utilization of the Miniserver. Maybe there is some issue there...
JoDehli
commented
2 years ago The got_effects is normally only triggered when a on command is triggered. Are you sure that you not use any of the lights in a automation in ha?
johny-mnemonic
commented
2 years ago I am sure I am not using any of the lights that are controlled by the scene sequence in Loxone, but I am using other lights on these light controllers in automations.
This was actually my first suspicion, that the automations are somehow misbehaving, but there was no trace from the time of issue and disabling the automations didn't help either.
For example in the first room, I have automation that works with jdev/sps/io/1071d041-014a-9e99-ffffd7846630eb23/AI3
Whole automation looks like this:
alias: Loxone - LED podlaha kuchyn
description: ""
trigger:
- platform: state
entity_id: light.led_podlaha_kuchyn
condition: []
action:
- choose:
- conditions:
- condition: state
entity_id: light.led_podlaha_kuchyn
state: "on"
sequence:
- service: light.turn_on
data:
brightness: "{{states.light.led_podlaha_kuchyn.attributes.brightness | int }}"
rgb_color: "{{states.light.led_podlaha_kuchyn.attributes.rgb_color | list }}"
target:
entity_id: light.led_pasek_kuchyn_podlaha
default:
- service: light.turn_off
target:
entity_id: light.led_pasek_kuchyn_podlaha
data: {}
mode: single
The entity light.led_podlaha_kuchyn equals to the Loxone uuid above.
This is one-way automation from Loxone to HA. There is also automation for direction from HA to Loxone, but that one is disabled for a long time and it is calling websocket directly just to set hsv, not to send plus or changeto commands.
It's similar for the other room as well, automation triggers are based on lights that are not controlled by the wall switches connected to Loxone plus input.
JoDehli
commented
2 years ago The light.led_podlaha_kuchyn is one light on light controller. So I think this is why you get a on command on the light controller. Can you disable all automations on one of the light controllers and try it if it still behaves strange. It think this could be the reason.
johny-mnemonic
commented
2 years ago Sure I can. Light controlled by HA are usually decorative or unimportant lights. Could you please elaborate a bit how you think this could be related? I think I already tried disabling all the related automations. Also there is no trace logged in HA for these automations around the time of issue.
EDIT: Now this is weird. I went on and disabled all the automations for the two rooms right after I added the comment above. Then I checked the state of the light in those and noticed that there is only decorative light turned-on in bathroom, where my wife and son were. I went there and asked what happened and they said main light was on when suddenly without any action they saw the rapid changes of scenes 😮 This is what I have found in HA. Disabling of the automations:
automation.loxone_led_podlaha_kuchyn - automation.turn_off 19:33:23
automation.loxone_galerka2_k2_zhasnout_duplicate - automation.turn_off 19:33:27
automation.loxone_galerka2_k2 - automation.turn_off 19:33:28
automation.loxone_galerka1_k2_zhasnout - automation.turn_off 19:33:30
automation.loxone_galerka1_k2 - automation.turn_off 19:33:32Light switching itself
2022-10-02 19:34:09.488 INFO (SyncWorker_6) [custom_components.loxone.light] we got effects: [''] ...
2022-10-02 19:34:09.490 INFO (SyncWorker_6) [custom_components.loxone.light] effect doesn't match mood ID , let's send 'plus'
2022-10-02 19:34:09.536 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/plus
2022-10-02 19:34:10.327 INFO (SyncWorker_4) [custom_components.loxone.light] we got effects: [''] ...
2022-10-02 19:34:10.328 INFO (SyncWorker_4) [custom_components.loxone.light] effect doesn't match mood ID , let's send 'plus'
2022-10-02 19:34:10.334 INFO (SyncWorker_4) [custom_components.loxone.light] we got effects: ['LED-50'] ...
2022-10-02 19:34:10.335 INFO (SyncWorker_4) [custom_components.loxone.light] change effect to: LED-50 ...
2022-10-02 19:34:10.336 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/plus
2022-10-02 19:34:10.338 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/changeTo/2
2022-10-02 19:34:10.941 INFO (SyncWorker_1) [custom_components.loxone.light] we got effects: [''] ...
2022-10-02 19:34:10.942 INFO (SyncWorker_1) [custom_components.loxone.light] effect doesn't match mood ID , let's send 'plus'
2022-10-02 19:34:10.943 INFO (SyncWorker_7) [custom_components.loxone.light] we got effects: ['Silné'] ...
2022-10-02 19:34:10.943 INFO (SyncWorker_7) [custom_components.loxone.light] change effect to: Silné ...
2022-10-02 19:34:10.946 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/plus
2022-10-02 19:34:10.947 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/changeTo/3I am clueless what just happened as according to timestamps it doesn't looks like turning off the automations directly triggered it. On the other hand it is too close to be totally unrelated. Especially as there was no action/input in Loxone to trigger it 🤷♂️
JoDehli
commented
2 years ago I really do not know how to help. The only thing what I can say is that only on a light on command the got effects are executed.
Do you have these problems longer or did you change something or added something?
I did not understand your last post. Is your problem know still the same with the disabled automation?
johny-mnemonic
commented
2 years ago I am having this issue for few months already and when it started it happened really rarely. It is getting more common lately though, which is why I am trying to dig into it as wife is complaining :-)
Would you be able to advice where to add logging so we can move further? I mean which function(s) are taking care of catching the state change in Loxone and updating the state of the light entity in HA?
I would like to add logging there to see what is going on there. It should help us to see what is received and how it is processed.
Then I would like to also add logging to see what triggered the got_effect() function. To se how it was called.
What happened today is that I disabled all the automations as you asked me. Then after not even a second the sequence you see in the log happened, switching the light scenes without any human input 👻 Which leads me to believe the issue really somehow relates to the automations, but I have no clue how as it happened after I disabled all of them and there is no trace about it in HA 🤯
JoDehli
commented
2 years ago event_handler is the function for each light. There is the state updated.
You must observe all lights on a light controller.
JoDehli
commented
2 years ago Ok I maybe have a idea. If you sent a automation with the wrong attributes maybe this could cause issues. What you can do is to edit the got_effect so that when you get a empty mood or effect then return an do nothing.
JoDehli
commented
2 years ago Change this: if len(effects) == 1:
To
if len(effects) == 1:
if effects == [""]:
return
Or something like this.
Means if the effects is a list with one item and if that item is a empty string do not plus and return. Hope you understand what I mean. Make sure you indent right
johny-mnemonic
commented
2 years ago Sure, understand. That looks like a good workaround. Thanks.
I would still like to find the root cause, so I am going to add some logging and see what is going on there.
JoDehli
commented
2 years ago @johny-mnemonic I changed something on the light. Maybe this fixes also your problem. I do not know because I can not reproduce your error. But you can give it a try.
The source is under a new branch: https://github.com/JoDehli/PyLoxone/tree/lights_in_group
johny-mnemonic
commented
2 years ago @JoDehli Thanks, but seems like the issue is somewhere else than in got_effect() function. That one is merely delivering it.
As you already said "only on a light on command the got effects are executed" and it really seems like the culprit is somewhere where the light on command is triggered.
Also the assumption that blank effect means something is wrong was wrong. Whenever you for example activate light output from the app (or by input tight to that output) it says "manual" in Loxone UI instead of scene name and it doesn't send any scene/mood to HA. So it is completely valid to not have effect on the input of got_effect() function.
Right now I have all the automations related to Loxone disabled in the troubled rooms and I tried the code from the lights_in_group branch and the only difference is it now turns the lights off instead of going through the moods/scenes by sending plus command 🤷♂️
Following are logs of what happened almost right after I restarted HA with the new code. Bootup + first wave of state updates from Loxone to HA (it does so for all lights, but here I mention only the one we are interested in)
2022-10-08 19:41:57.791 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration loxone which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2022-10-08 19:43:41.962 ERROR (MainThread) [homeassistant.components.binary_sensor] The loxone platform for the binary_sensor integration does not support platform setup. Please remove it from your config.
2022-10-08 19:43:52.845 INFO (MainThread) [custom_components.loxone] loxone discovered
2022-10-08 19:45:47.957 INFO (MainThread) [custom_components.loxone.light] Event1-moods: activeMoods [1] requested HA update
2022-10-08 19:45:47.989 INFO (MainThread) [custom_components.loxone.light] Event1-moods: moodList [{"name":"Bodovky","id":1,"static":false,"used":1},{"name":"LED linka","id":2,"static":false,"used":2},{"name":"LED podlaha","id":3,"static":false,"used":1},{"name":"Vyp.","id":778,"static":true},{"name":"Více světla","id":777,"static":false}] requested HA updateInterestingly there was second update of all lights from Loxone to HA after a while:
2022-10-08 19:47:32.347 INFO (MainThread) [custom_components.loxone.light] Event1-moods: activeMoods [1] requested HA update
2022-10-08 19:47:32.348 INFO (MainThread) [custom_components.loxone.light] Event1-moods: moodList [{"name":"Bodovky","id":1,"static":false,"used":1},{"name":"LED linka","id":2,"static":false,"used":2},{"name":"LED podlaha","id":3,"static":false,"used":1},{"name":"Vyp.","id":778,"static":true},{"name":"Více světla","id":777,"static":false}] requested HA updateThen we were all sitting in Living room, when kitchen suddenly went dark without any activity from our side:
2022-10-08 20:04:37.081 INFO (SyncWorker_8) [custom_components.loxone.light] Turn_on: Got turn_on call.
2022-10-08 20:04:37.082 INFO (SyncWorker_8) [custom_components.loxone.light] Got_effect: got effects: ['']
2022-10-08 20:04:37.083 INFO (SyncWorker_8) [custom_components.loxone.light] Got_effect: received blank effect
2022-10-08 20:04:37.083 INFO (SyncWorker_8) [custom_components.loxone.light] Got_effect: effect doesn't match mood ID , let's send 'off'
2022-10-08 20:04:37.084 INFO (SyncWorker_8) [custom_components.loxone.light] Turn_on: got effect: None for 1071d041-014a-9e99-ffffd7846630eb23 in args, let's call got_effect.
2022-10-08 20:04:37.084 INFO (SyncWorker_8) [custom_components.loxone.light] Got_effect: got effects: ['']
2022-10-08 20:04:37.085 INFO (SyncWorker_8) [custom_components.loxone.light] Got_effect: received blank effect
2022-10-08 20:04:37.085 INFO (SyncWorker_8) [custom_components.loxone.light] Got_effect: effect doesn't match mood ID , let's send 'off'
2022-10-08 20:04:37.091 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d041-014a-9e99-ffffd7846630eb23/off
2022-10-08 20:04:37.110 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d041-014a-9e99-ffffd7846630eb23/offIt is weird that got_effect() was called from the turn_on() function twice 🤔
Here are the code changes for the logging you see above from light.py
def got_effect(self, **kwargs):
effects = kwargs["effect"].split(",")
_LOGGER.info("Got_effect: got effects: {}".format(effects))
if len(effects) == 1:
if effects == [""]:
_LOGGER.info("Got_effect: received blank effect")
#return
mood_id = self.get_id_by_moodname(kwargs["effect"])
if mood_id != kwargs["effect"]:
_LOGGER.info("Got_effect: changing effect to {}".format(kwargs["effect"]))
self.hass.bus.async_fire(
SENDDOMAIN,
dict(uuid=self.uuidAction, value="changeTo/{}".format(mood_id)),
)
else:
_LOGGER.info("Got_effect: effect {} doesn't match mood ID {}, let's send 'off'".format(kwargs["effect"], mood_id))
self.hass.bus.async_fire(
SENDDOMAIN,
dict(uuid=self.uuidAction, value="off"),
)
def turn_on(self, **kwargs) -> None:
_LOGGER.info("Turn_on: Got turn_on call.")
if ATTR_EFFECT in kwargs:
_LOGGER.info("Turn_on: got effect: {} for {} in args, let's call got_effect.".format(self.got_effect(**kwargs), self.uuidAction))
self.got_effect(**kwargs)
elif kwargs == {}:
if self.state == STATE_OFF:
_LOGGER.info("Turn_on: got no attributes in args and light is off, let's send 'plus' command to {}.".format(self.uuidAction))
self.hass.bus.async_fire(SENDDOMAIN, dict(uuid=self.uuidAction, value="plus"))
self.schedule_update_ha_state()
async def event_handler(self, event):
request_update = False
if self.uuidAction in event.data:
self._state = event.data[self.uuidAction]
_LOGGER.info("Event1-moods: action {} requested HA update".format(event.data[self.uuidAction]))
request_update = True
if self.states["activeMoods"] in event.data:
self._active_moods = eval(event.data[self.states["activeMoods"]])
_LOGGER.info("Event1-moods: activeMoods {} requested HA update".format(event.data[self.states["activeMoods"]]))
request_update = True
if self.states["moodList"] in event.data:
_LOGGER.info("Event1-moods: moodList {} requested HA update".format(event.data[self.states["moodList"]]))
event.data[self.states["moodList"]] = event.data[
self.states["moodList"]
].replace("true", "True")
event.data[self.states["moodList"]] = event.data[
self.states["moodList"]
].replace("false", "False")
self._moodlist = eval(event.data[self.states["moodList"]])
request_update = TrueOh and in the middle of writing this update the second room got dark on it's own as well :-D
2022-10-08 20:46:55.247 INFO (SyncWorker_6) [custom_components.loxone.light] Turn_on: Got turn_on call.
2022-10-08 20:46:55.248 INFO (SyncWorker_6) [custom_components.loxone.light] Got_effect: got effects: ['']
2022-10-08 20:46:55.248 INFO (SyncWorker_6) [custom_components.loxone.light] Got_effect: received blank effect
2022-10-08 20:46:55.248 INFO (SyncWorker_6) [custom_components.loxone.light] Got_effect: effect doesn't match mood ID , let's send 'off'
2022-10-08 20:46:55.249 INFO (SyncWorker_6) [custom_components.loxone.light] Turn_on: got effect: None for 1071d24e-001e-6861-ffffd7846630eb23 in args, let's call got_effect.
2022-10-08 20:46:55.249 INFO (SyncWorker_6) [custom_components.loxone.light] Got_effect: got effects: ['']
2022-10-08 20:46:55.249 INFO (SyncWorker_6) [custom_components.loxone.light] Got_effect: received blank effect
2022-10-08 20:46:55.249 INFO (SyncWorker_6) [custom_components.loxone.light] Got_effect: effect doesn't match mood ID , let's send 'off'
2022-10-08 20:46:55.253 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/off
2022-10-08 20:46:55.255 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/offSo seems like I will need to add logging to different places from where the turn_on() function is executed.
And probably uncomment that #return to not act on these turn_on calls.
JoDehli
commented
2 years ago @johny-mnemonic Ok I updated again the branch and I made some changes on the on and off command. But I think you problem is a different problem.
I do not believe that all your automations are disabled. Maybe it is a automatic day and night command or something else. Because ha does not switch any light on or off. There must be something happen in the background.
But try the branch because I saw that the on command on larger systems can be cause issues as it was implemented in the old version. I made all calls now async and this should be much more robust on larger systems and no on command should be skipped.
This branch again: https://github.com/JoDehli/PyLoxone/tree/lights_in_group
johny-mnemonic
commented
2 years ago @JoDehli I have a reproducer.
At least with the latest version from the branch above it happens in 100% cases.
You probably wouldn't believe it, but it really is 100%.
Whenever I have the light in one of those two rooms ON and I open the Lovelace dashboard (either on PC or Android app), which probably tries to update the UI with the current state, it sends the off command to that room.
And if I then try to use the switch to turn-on the light, it immediately sends the off command again. So the only way to actually turn-on the light in that room is using HA. There is no way to turn on the light there using Loxone as it is immediately turned off by HA.
This pattern repeats in the log:
2022-10-11 20:36:09.411 INFO (MainThread) [custom_components.loxone.light] Event1-moods: activeMoods [1] requested HA update
2022-10-11 20:36:48.299 INFO (MainThread) [custom_components.loxone.light] Turn_on: Got turn_on call.
2022-10-11 20:36:48.303 INFO (MainThread) [custom_components.loxone.light] Turn_on: got effect: <coroutine object LoxonelightcontrollerV2.got_effect at 0xffff70b730d0> for 1071d24e-001e-6861-ffffd7846630eb23 in args, let's call got_effect.
2022-10-11 20:36:48.304 INFO (MainThread) [custom_components.loxone.light] Got_effect: got effects: ['']
2022-10-11 20:36:48.304 INFO (MainThread) [custom_components.loxone.light] Got_effect: received blank effect
2022-10-11 20:36:48.305 INFO (MainThread) [custom_components.loxone.light] Got_effect: effect doesn't match mood ID , let's send 'off'
2022-10-11 20:36:48.308 INFO (MainThread) [custom_components.loxone.api] send command: jdev/sps/io/1071d24e-001e-6861-ffffd7846630eb23/off
2022-10-11 20:36:49.195 INFO (MainThread) [custom_components.loxone.light] Event1-moods: activeMoods [778] requested HA updateFirst line is apparently the update from Loxone to HA, that the mood ID=1 got activated in Loxone. But instead of triggering only the HA update, it triggers the call to turn_on without any effect, which now sends off while before I opened this issue it was sending plus command.
The last line is also update from Loxone, but the mood with ID 778 is "turned off", so that is harmless.
I am going to try to go through my Lovelace configuration and cards to see if I can find anything suspicious.
johny-mnemonic
commented
2 years ago OK, found it. I am using custom Light Entity card to be able to select light effect from HA and I have it only for these two problematic rooms. It is apparently sending light turn on when it gets update of the state of the light entity 🤷♂️ It was weird, that these troubles were only present in the evening, never during day or morning. Now it's explained. In the evening when I have PC turned ON, I usually have HA opened in my browser :-)
Seems like switching to async made PyLoxone more reliable/consistent as it was never so reproducible. I am pretty sure I was debugging it with a phone with open HA app in one hand and pressing wall switch with second hand in the past and it only happened sometimes, not always like now.
JoDehli
commented
2 years ago @johny-mnemonic I was thinking that it could come from a different implementation of a custom entity. Because the other issue I have there is also a custom entity in use.
So what does it mean for the issue? Can you fix it by switching back to the standard loxone switches?
johny-mnemonic
commented
2 years ago Sure. I just removed the custom entity from the dashboard. We can close the issue.
The only question is, whether the switch from plus to off here, was the right decision. Or in general which changes in that branch to merge and which to drop...
I would say that switching to async is definitely the move in the right direction but I have no clue about the rest.
Also do you have any advice how to discover such issue easier? Where to add logging to quickly see whether the light_on (or any other service call) is not issued by PyLoxone and is comming from outside?
JoDehli
commented
1 year ago @johny-mnemonic I have no advice do discover such issue easier. It is every time difficult. I think the best way is to add log messages as you did it. For me it was a great enlightenment that it makes a difference if you use standard elements or custom elements. Next time this is the first question I will ask. :-)
I will close this issue.
johny-mnemonic
commented
1 year ago @JoDehli yeah, this was really insidious issue 😄 Thanks again for help!
Which Model do you use from loxone? Miniserver? Gen1 or Gen2? Gen1 Which software version does your loxone use? 12.2.12.1 How did you install HomeAssistant? Over Hassio oder manual install? Hassio on Debian 11 Which Version do you use of HomeAssistant? 2022.9.7 Describe the bug When I enter the room and use a switch on the wall to turn-on the light it turns-on the first scene, but then it immediately cycles through the available scenes. Sometimes going through all of them and switching the light off, sometimes stopping at some of the other scenes. The switch is wired switch connected to Loxone input and going to
plusinput on the Light Controller block. I first thought it is a issue in Loxone, but as I haven't found anything and this happens only in two rooms in which I have some lights integrated by HA, I started digging in HA. When raising the log level of PyLoxone to debug I have found one event when it sentpluscommands to the light controller. I then tried to disable automations in HA, which are controlling lights present in those rooms, but that didn't remove the issue.The issue with using debug level of log is that it produces so much logs it is killing my HA (running on RPi 3). Combined with the fact this happens only few times a week, I ended up switching logs to info level and modifying the logging of PyLoxone to add log messages with
infolevel to interesting places.Code changes: light.py:
api.py:
I am not sure I understood correctly what the blocks in
light.pyare doing, so the text of logging messages might not make sense to you, but here are the logs from the events when the issue happend:I am not sure what triggers this behavior, but it looks like when it happens either HA or PyLoxone is sending
pluscommands till it finds some scene it can switch to. To find the root cause I would need some help with adding log messages to proper places as the behavior above would be invisible even with debug log, as thatgot_effectfunction is not logging it's actions even on debug. I am not complaining, it makes sense, but for hunting this ghost we need very targeted logging. Like adding message that will show us what came from Miniserver and also whether sending thesepluscommands is somehow triggered by HA or done PyLoxone itself.My working theory is, that when there comes a change of state of light controller from Miniserver but it doesn't contain the name of currently used scene/effect or fetching it is too slow and times out, PyLoxone gets confused and starts sending
pluscommands 🤷♂️Could you please advice how to improve the logging to finally catch this ghost? As it happens in kitchen and main bathroom for few months already the WAF is getting pretty low 😀