Stability Issues detected in logs on latest version about ha-lifx-beta HOT 18 CLOSED

I've just pushed 2022.06.06 that contains the latest refactor. If this doesn't work, there must be something weird happening with the REST sensor and I'll have to try and reproduce that. I'm not getting any of those warnings on my test or production instances.

from ha-lifx-beta.

I've got that one installed now, so will give it a day and see what happens.

from ha-lifx-beta.

That's weird. Those lines have been in the LIFX integration since way before I even started using Home Assistant. I'll have to configure a REST sensor and see if I can reproduce the issue.

from ha-lifx-beta.

Actually, no. I think I know what the problem is. I need to update the component from the changes I made to core anyway, which should fix this.

It wasn't what I thought it was, but there's an update incoming regardless.

from ha-lifx-beta.

Ok cool, let me know once it's out and will give it a test. I've gone back to 2022.06.03 for the moment.

from ha-lifx-beta.

Back to this warning now:

I've turned on debugging so will restart in a moment and collect some logs. If there is anything in particular you are looking out for, let me know.

from ha-lifx-beta.

The refactor should reduce the occurrence of that warning but it wasn't designed to eliminate it. The fact that there are 102 occurrences of this however indicates that something is wrong somewhere.

First, check the Home Assistant network configuration to ensure that it is configured correctly.

Otherwise, evaluate what's running on your network to determine if anything could be causing excessive network traffic: all direct communication with LIFX devices is done via UDP which means there is no IP session establishment and no network protocol level acknowledgement or retries.

I seem to recall that you might be using the Photons Interactor add-on: if that's correct, please try turning that off to see if it improves the stability of the integration. Older releases of Interactor were particularly aggressive about updating state information and would overwhelm most wifi networks with traffic.

from ha-lifx-beta.

The refactor should reduce the occurrence of that warning but it wasn't designed to eliminate it. The fact that there are 102 occurrences of this however indicates that something is wrong somewhere.

First, check the Home Assistant network configuration to ensure that it is configured correctly.

Its in Docker, so not much I can do in the way of config, it is setup as per guidelines.

I seem to recall that you might be using the Photons Interactor add-on: if that's correct, please try turning that off to see if it improves the stability of the integration. Older releases of Interactor were particularly aggressive about updating state information and would overwhelm most wifi networks with traffic.

Yer was going to, but didn't in the end, couldn't find any helpful documentation on it for docker in terms of actually interacting with it.

In terms of network congestion, possible, but hard to pin down without some logger in the middle of network, but can't say I've experienced any slow-downs or seeing any issues with other Wi-Fi connected devices and the bulbs and other things respond instantly.
All I can say is that this warning did not appear before 2022.5 and before this custom integration. So whether it was supressed or just didn't occur?!

Will see if the debug log comes up with anymore information.

from ha-lifx-beta.

The fact that it's in Docker means you need to check the network configuration because Docker has a tendency to break discovery and Home Assistant changed the way they handle networking recently. Please review the network configuration documentation and validate that your Docker configuration and Home Assistant agree on what the networking actually is.

If you're running Home Assistant OS on a Raspberry Pi, you should only be using one of the two network interfaces, preferably physical ethernet, unless you really know what you're doing and have segregated your IoT or Wifi network onto a different IP segment.

from ha-lifx-beta.

Its using network mode host as required per the documentation https://www.home-assistant.io/installation/linux

My WiFi and HA are on segregated LANs with firewall policies between the two as required, though HA has almost unrestricted access to IoT devices in that portion of the LAN. Each of these are on static IPs.
As a result Lifx lights are manually configured in a configuration file in HA with their static IP.
Perhaps not using the native discovery is throwing the error, when it shouldn't be attempting to discover them when I've manually listed them in the config?

That warning is probably because some bulbs are currently offline, and if that is the reason then that is fine, if you don't think it is, happy to continue investigating and providing logs.

from ha-lifx-beta.

Manually configuring LIFX bulbs doesn't actually disable discovery, it just restricts it to the specific IP addresses you've manually configured as broadcast targets. It's network trickery that works because UDP is a pretty basic protocol that has no concept of an actual broadcast address.

I'm pretty sure the manually configured offline bulbs are your problem here, but I'm not sure specifically why, because I've never manually configured my bulbs. It's easy enough to test: remove the manual configuration for the bulbs you know are offline and see if that resolves the issue.

In the meantime, I'm going to reproduce it here by manually configuring bulbs that just don't exist to see what the integration does.

from ha-lifx-beta.

I'm pretty sure the manually configured offline bulbs are your problem here

Turns out my assumption here is wrong, or at least, I can't reproduce the issue when I manually configure bulbs. Regardless of whether bulbs are discovered automatically or are manually configured, the integration only starts logging things after it connects to each bulb. If it never connects to a bulb, e.g. if the bulb is offline when HASS starts, then it just marks it unavailable.

Having said that, it will still attempt to discover all the bulbs every 10 seconds, which in the case of manual configuration is a UDP packet per entry as opposed to a UDP packet per network segment, but that's highly unlikely to be the cause of any network issues.

I am now really curious to see your debug logs.

from ha-lifx-beta.

Here is some

2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.162 (d0:73:d5:2c:bb:30)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.156 (d0:73:d5:44:5a:35)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.169 (d0:73:d5:2c:3a:09)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.194 (d0:73:d5:55:8f:75)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.191 (d0:73:d5:55:5d:8e)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.172 (d0:73:d5:27:56:fe)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.183 (d0:73:d5:39:f3:89)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.161 (d0:73:d5:29:77:15)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.178 (d0:73:d5:27:b0:3f)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.176 (d0:73:d5:27:77:ae)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.165 (d0:73:d5:2c:9d:25)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.185 (d0:73:d5:2f:37:ba)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.175 (d0:73:d5:25:c1:1e)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.177 (d0:73:d5:27:bc:1c)
2022-06-13 13:14:41 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.173 (d0:73:d5:27:b0:b0)
2022-06-13 13:14:42 DEBUG (MainThread) [custom_components.lifx.light] Entity created for Back Door (d0:73:d5:6d:65:df)
2022-06-13 13:14:42 DEBUG (MainThread) [custom_components.lifx.light] Entity created for Lounge Lamp (d0:73:d5:39:f3:89)
2022-06-13 13:14:42 DEBUG (MainThread) [custom_components.lifx.light] Entity created for Stairs Top (d0:73:d5:55:8f:75)
2022-06-13 13:14:42 DEBUG (MainThread) [custom_components.lifx.light] Entity created for Lamp (d0:73:d5:55:90:ca)
2022-06-13 13:31:26 DEBUG (MainThread) [custom_components.lifx.light] First discovery response received from 192.168.10.192 (d0:73:d5:6b:a6:02)
2022-06-13 13:31:26 DEBUG (MainThread) [custom_components.lifx.light] Entity created for Toilet (d0:73:d5:6b:a6:02)
2022-06-13 13:33:13 WARNING (MainThread) [homeassistant.components.light] Updating lifx light took longer than the scheduled update interval 0:00:10
2022-06-13 13:33:13 WARNING (MainThread) [homeassistant.helpers.entity] Update of light.toilet is taking over 10 seconds
2022-06-13 13:33:33 WARNING (MainThread) [homeassistant.components.light] Updating lifx light took longer than the scheduled update interval 0:00:10
2022-06-13 13:33:33 WARNING (MainThread) [homeassistant.helpers.entity] Update of light.toilet is taking over 10 seconds
2022-06-13 13:33:53 WARNING (MainThread) [homeassistant.components.light] Updating lifx light took longer than the scheduled update interval 0:00:10
2022-06-13 13:33:53 WARNING (MainThread) [homeassistant.helpers.entity] Update of light.toilet is taking over 10 seconds
2022-06-13 13:34:13 WARNING (MainThread) [homeassistant.components.light] Updating lifx light took longer than the scheduled update interval 0:00:10
2022-06-13 13:34:13 WARNING (MainThread) [homeassistant.helpers.entity] Update of light.toilet is taking over 10 seconds
2022-06-13 13:34:31 DEBUG (MainThread) [custom_components.lifx.light] Disconnected from Toilet (d0:73:d5:6b:a6:02)
2022-06-13 13:34:33 WARNING (MainThread) [homeassistant.components.light] Updating lifx light took longer than the scheduled update interval 0:00:10

(Edited to fix log output formatting)

from ha-lifx-beta.

The integration is getting at least a discovery response and version response so it creates the entity, but then never gets a response to the request for current state so it disconnects from the bulb. Can you run this for a while and then review the logs to see if it's always the Toilet light or if other lights exhibit the same problem?

If it's just the Toilet light, would it be possible to move that particular bulb to a location closer to your wifi AP to see if it's a pure connectivity issue, i.e. if the wifi signal is low enough in that location that the bulb is having difficulty either receiving or sending packets.

from ha-lifx-beta.

2022-06-13 15:10:28 DEBUG (MainThread) [custom_components.lifx.light] Reconnected to Toilet (d0:73:d5:6b:a6:02)

Turning on the Toilet, it did connect, turning it off again, same info appears in the logs:

2022-06-13 15:12:14 WARNING (MainThread) [homeassistant.components.light] Updating lifx light took longer than the scheduled update interval 0:00:10 2022-06-13 15:12:14 WARNING (MainThread) [homeassistant.helpers.entity] Update of light.toilet is taking over 10 seconds

I did just also get a disconnect for the following bulb "hall":

2022-06-13 14:38:38 DEBUG (MainThread) [custom_components.lifx.light] Disconnected from Hall (d0:73:d5:2d:35:58)

Nothing in between that, and me power cycling it a few moments ago:

2022-06-13 15:09:43 DEBUG (MainThread) [custom_components.lifx.light] Reconnected to Hall (d0:73:d5:2d:35:58)

Not sure why HA is complaining about the Toilet bulb so often, given the bathroom, and 4 other lights are currently off right now as well. Bathroom and Toilet are both Clean bulbs and don't constantly have power.
Additionally HA got discconected from the Hall (no idea why, Lifx couldnt connect either), but it doesn't complain in the logs it was unresponsive.

from ha-lifx-beta.

If you power off a bulb after Home Assistant has discovered it, then this is expected. Home Assistant will continue to try and get status from the bulb every 10 seconds until the underlying library flags it as disconnected which happens 90 seconds after the last packet was received.

Once flagged as disconnected/unavailable, Home Assistant will stop attempting to update a bulb's status until it becomes available, which will only happen if/when the bulb is successfully rediscovered. Given your manual configuration, this should happen within 10 seconds of the bulb connecting to your wifi network.

Your first log output shows Home Assistant disconnecting from the Toilet bulb, which is expected if it got powered off. If it was still off when you power cycled Home Assistant, it wouldn't have been discovered at all, so you'd get no log entries until it powers on again.

For your use case, I would consider it "working as expected" if Home Assistant discovers a bulb within 20 seconds of it powering on and if Home Assistant marks a bulb unavailable within 100 seconds of it powering off.

from ha-lifx-beta.

Fair enough, then yer seems to be working as expected, least you got some test logs out of it and could test an edge case.

Appreciate the help, and I will just ignore the logs knowing that it is expected behaviour.

from ha-lifx-beta.

Last note: disable debug logging. :) I'd also be curious to know if removing the manual configuration makes things faster or slower for discovery and disconnection.

from ha-lifx-beta.