[BUG] Lamp becomes unavailable every hour

[szymucha94]

Describe the bug Lamp becomes unavailable at least once every hour when on. State "off" is maintained in HA even for days. Lamp is connected to wifi and it does not disconnect.

To Reproduce Turn on the light Enable the "fast random" mode Leave it on for 1 hour Check lamp entity history in HA

Expected behavior Lamp should not be "unavailable" when on and with active wifi connection.

Additional context versions used: FW: Firmware: 2022.5.1 (Jun 14 2022, 22:21:11) esphome addon: Current version: 2022.6.1

[szymucha94]

Testing now with updated FW to the one based on 2022.6.1

[szymucha94]

Same problem on 2022.6.1.

[mmakaay]

I haven't seen this behavior on any of my three lamps, and with my development lamp, I did some really long tests with exactly that effect without issues. Maybe something changed in ESPHome core that now triggers this, so I will flash my dev lamp with the latest ESPHome code and see if I can reproduce this behavior.

One known thing that can trigger this, is excessive logging. The more you log, the less time the WiFi component has to keep up with network traffic. So one thing you could check, is what your logger configuration looks like. From the core config package:

# The log level can be raised when needed for debugging the firmware. For
# production, a low log level is recommended. Mainly because high volume log
# output might interfere with the API/WiFi connection stability. So when
# raising the log level, beware that you might see dropped connections from
# Home Assistant and the network log viewer.
logger:
  level: WARN

[szymucha94]

good point, by default I had "info" set. Changed to "warning" and testing this now. Thanks!

[mmakaay]

Ah, that might already fix the issue for you :-) Please let me know if this fixes the issue. If not, I'll investige on my lamp.

[szymucha94]

Unfortunately it still becomes unavailable. 1 time during last hour so far

I'll redo testing now with additional ping in the background. I'm sure on 2022.5.1 wifi was not disconnecting, but I'm not so sure about 2022.6.1

[szymucha94]

Okay, I've got something... lamp disconnected from wifi network. It's interesting because all other active wifi devices (for example two esp powered xiaomi air purifiers and one humidifier with much worse RSSI) remain connected. Also lamp didn't do that on original firmware. I will do one more test - this time without "fast random" mode

[szymucha94]

Issue does not seem to occur (so far) when special effects are disabled and lamp is just shining blue. I'll let you know after 2-3 hours if it remains stable. Edit: after 2 hours still all is fine, not a single drop in ping:

[mmakaay]

I'm on the train right now, so I can't check for myself (at least not without spooking the cleaning lady who's in my home right now with flashing lights ;-) ), but could you verify if the logging is actually quiet right now? (using the ESPHome dashboard log connection for example)

I know that some extra log messages were added to the light integration, and possibly those are sent out using the WARN log level. In that case, tuning the log level to ERROR (or leaving the logger out completely if you don't use it) would help.

When the logging is quiet, then tuning down the log level any further wouldn't help.

[szymucha94]

meh, at first I've just checked configuration.yaml thinking this is the loglevel of whole hass... Just flashed the lamp, will let you know.

[szymucha94]

Nope, changing log level to error didn't help. Lamp is still disconnecting every hour in this mode. Even setting loglevel to "NONE" doesn't help.

[mmakaay]

I will try it on my lamp. The next to days, I'm a lot away from home, but this weekend I should be able to do a test run.

[szymucha94]

Thank you!

[mmakaay]

I had a chance to do some testing, and my lamp is running 100% stable with DEBUG level logging enabled. This means that I get these log messages, every time the fast random effect changes color:

[20:39:27][I][light:392]: 'Bedside Lamp Bedroom RGBWW Light' - Keeping current color mode RGB for call without color mode.
[20:39:27][D][light:035]: 'Bedside Lamp Bedroom RGBWW Light' Setting:
[20:39:27][D][light:058]:   Red: 81%, Green: 37%, Blue: 100%
[20:39:27][D][light:084]:   Transition length: 3.0s

And even with this, I see no connection drops.

So I'm afraid I'm unable to reproduce the behavior that you're seeing.

[szymucha94]

Could you please tell me what is your config?

[mmakaay]

Basically the example config, and then some extras added (I've got an extra microwave presence sensor built-in).

But I just saw one little hickup after continuously running the fast random effect for a couple of hours. It came back right after that, so I don't think I would have even noticed it had I not added the status sensor.

I have quite a bit of logging, which might be of impact, But when dropouts like this also happen with logging disabled, it's still likely that the device being busy doing stuff other than managing the HA connection / WiFi. This lamp uses an ESP32 that has only one core, which makes it more susceptible to dropping the connection when the device is busy. And with the fast random effect, the CPU is basically busy all the time. Not sure if I can improve on that.

[szymucha94]

Thanks for checking. I guess I will work around this, repeat sending the command if lamp disconnects or something. But if you manage to somehow improve this in the future it'd be nice tho :)

Cheers!

[mmakaay]

Yeah, that's why I didn't close the issue yet. I do want to go over the code to see if there are bits that might be hogging the CPU for too long. It's not optimal this way, and not giving up without a fight 😄

[szymucha94]

One more observation. Every time lamp disconnects it also turns off the light for about 0,5s or less. At first I thought the algorithm behind picking random color just picks unsupported or problematic setting.

[mmakaay]

That last thing shouldn't happen. All colors are valid. So it's definitely related to the reconnecting.

[andyboeh]

You're probably facing an annoying and long-standig bug in ESPHome that happens on nearly all my ESPHome devices (it never happened on Tasmota, that's why I suspect it's ESPHome). What improved the situation dramatically was adding a separate WiFi AP with WMM disabled. Also, updating my Router's firmware to a newer build (I'm using OpenWrt) improved the situation.

See https://community.home-assistant.io/t/device-going-unavailable/347769

[szymucha94]

You're probably facing an annoying and long-standig bug in ESPHome that happens on nearly all my ESPHome devices (it never happened on Tasmota, that's why I suspect it's ESPHome). What improved the situation dramatically was adding a separate WiFi AP with WMM disabled. Also, updating my Router's firmware to a newer build (I'm using OpenWrt) improved the situation.

See https://community.home-assistant.io/t/device-going-unavailable/347769

Hi, I'm already using openwrt, but with WMM enabled. I will consider creating separate AP directly on the HA hypervisor to mitigate this problem, especially since under newest ESPhome build it disconnects every 30 minutes, not 1h. Thank you!

[andyboeh]

Yeah, it might also depend on the WiFi chipset: I never experienced this with mt76 radios, only with QCA chipsets.

[szymucha94]

Nope, with intel chipset, WMM disabled, channel 6 selected and "fast_connect = true" lamp is still reconnecting every <1h.