ESPHome disconnections.. all at once

Will · October 25, 2024, 2:44pm

I am seeing frequent “loss of communication”. I would understand if losing the connection to a specific device from time to time. However, as the screenshot below shows, ALL my devices are lost all at once:

2024-10-29 09:25:45.144 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-office' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-29 09:25:45.145 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-lr-velux' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-29 09:25:45.146 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-left' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-29 09:25:45.147 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-right' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay

and magically come back a few seconds later:

2024-10-29 09:25:55.980 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-office' changed from UNKNOWN: Connecting to esph-office.some.domain:6053 to ONLINE
2024-10-29 09:25:56.008 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-lr-velux' changed from UNKNOWN: Connecting to esph-lr-velux.some.domain:6053 to ONLINE
2024-10-29 09:25:56.010 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-left' changed from UNKNOWN: Connecting to esph-kitchen-shade-left.some.domain:6053 to ONLINE
2024-10-29 09:25:56.038 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-right' changed from UNKNOWN: Connecting to esph-kitchen-shade-right.some.domain:6053 to ONLINE

The ESP32 I am using are operating on mains (no battery) so they should work pretty solid.

Could that be an issue with the ESPHome binding ?

edit: replaced old screenshots with the text version of the logs, better for the search…

rlkoshak · October 25, 2024, 2:56pm

Please don’t post screen shots of logs. Use text and code fences.

```
code goes here
```

Does this binding have a bridge Thing? If so when that Thing goes offline all the Things under that Thing will go offline (e.g. if the MQTT Broker Thing goes offline all the MQTT Things using that Broker will go OFFLINE too).

The error is “COMMUNICATION_ERROR” so the binding lost the connection to the devices for some reason. So this is definitely going to be related to the ESPHome binding. Maybe putting the binding into debug logging would be informative. Usually a binding will log a warning or error to openhab.log when it encounters a problem like this, but it definitely will in debug level logging.

seime · October 25, 2024, 8:42pm

Which version are you running?

Please provide debug logs.

Brg

Will · October 26, 2024, 7:20am

Indeed, the logs as text would have been better but I have missed those errors a few times and I wanted this time to catch them quick.
This binding does not have a bridge Thing.

I will put the binding in debug and see if something useful shows up.

I am running ESPHome Binding:

Source 3rd Party (jar)
Version 4.1.0.202407071831
Type binding
Content Type OSGi Bundle
Provisioned With Karaf

@seime your question suprised me and I was about to answer the latest but I realize you may be asking which “flavor” ? I see there are 2 add-ons:

Is there a good and a bad one and I missed the switch ?

I think I may have installed back then using the JAR but if I did so, it was likely becasue it was the only option (back then).

Will · October 26, 2024, 8:29am

I now switched to the store version. Let’s see.

seime · October 26, 2024, 7:47pm

Yes you had a direct install and not installed via the marketplace.

The marketplace does not support updates nor inform the user about available updates. So someone needs to step up and improve this functionality. Could that be you?

Brg

Will · October 27, 2024, 2:49pm

@seime one at a time

I was thinking the switch to the marketplace version could have fixed the issue but it did not: I just caught an occurence. I could not turn on debug since the marketplace version does not seem to offer the option (the jar previously installed did have this single option):"

2024-10-27 15:44:01.053 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-left' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-27 15:44:01.054 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-lightning-01' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-27 15:44:01.057 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-right' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-27 15:44:01.060 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-office' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-27 15:44:01.063 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-lr-velux' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
==>

seime · October 27, 2024, 9:05pm

Cannot tell why the ui doesn’t support setting log on this binding. Does it show something for other marketplace bindings that doesn’t use the org.openhab package prefix? Anyway you can set it via the cli. Package starts with no.seime.openhab…

What does the log for the devices say?

Pedro_Liberal · October 27, 2024, 9:36pm

@seime very similar indeed!

I know you’ll hate me for the screenshots but like @Will said, it’s quite hard to catch these errors because they happen sporadically.

For example, every esphome device is down:

But yet I have a few with webui and I can reach it:

This is what little I caught in the logs. I just see them going offline then initializing then sometimes online or they go back to offline:

I’ve increased to 15 (!!!) the number of retries before setting it to offline but it still goes off.

Edit: ah, finally caught something, though not much:


2024-10-27 21:36:28.653 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:99edda6a51' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 15 pings sent with 10 s delay
2024-10-27 21:36:28.654 [WARN ] [home.internal.handler.ESPHomeHandler] - [Duartes_ac] Ping responses lacking. Waited 15 times 10 seconds, total of 150. Assuming connection lost and disconnecting
2024-10-27 21:36:28.655 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:South_bedroom_ac' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 15 pings sent with 10 s delay
2024-10-27 21:36:28.656 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:Office_ac' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 15 pings sent with 10 s delay
2024-10-27 21:36:28.657 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:Duartes_ac' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 15 pings sent with 10 s delay

seime · October 28, 2024, 6:47am

@Will @Pedro_Liberal

I’m suspecting something stops reading the datastream on the binding side, so ping rsp and other packets remain unprocessed.

Are you using api encryption or plaintext password? (2 different packet formats).

Also, please provide (in PM) a TRACE level log from where it works fine until this problem starts.

BRG

Will · October 28, 2024, 7:40am

I checked a few and yes, they show something.

But indeed, most of those I checked are org.openhab.*
I guess the one above as well.

So I don’t think I have addons with config that are not org.openhab.*
I do know, I had one option: log level when using the Jar.

Since I did not know the name of your package @seime I had to search

bundle:list  -s

tada:

358 │ Active │  80 │ 4.1.0.202409231705    │ no.seime.openhab.binding.esphome

So I ran (in Karaf):

log:set DEBUG no.seime.openhab.binding.esphome

which visibly (seeing the logs) worked.
I am now monitoring.

Will · October 28, 2024, 7:43am

and I missed that one. I am using:

api:
  encryption:
      key: !secret encryption_key

and

seime · October 28, 2024, 8:04am

Seems to be working if installed directly into addons folder, but not via marketplace:

Probably a bug in the marketplace bundle (but has to be verified, I’m using a custom version of that bundle).

Please provide TRACE level log! (Yes it will be huge if many devices )

Pedro_Liberal · October 28, 2024, 8:18am

Most devices have no security and one device in plaintext. Yes I’ll have to get around to address that eventually…

Will · October 28, 2024, 8:32am

@Pedro_Liberal that’s actually good, between the 2 of us, we have all the cases and yet we get the issue. So auth is probably not the issue.

emiel · October 29, 2024, 6:17am

same here, as mentioned in the other topic. When all ESP’s are offline, they all mention that the Binding is missing, reinstalling it solves the problem.

Will · October 29, 2024, 7:34am

I am still in debug and monitored the whole day yesterday, of course once monitoring, the issue does not occur

Will · October 29, 2024, 8:32am

Finally got a failure. @seime will hate me since I am still “only” in debug but that’s what I have for now.

It starts with:

2024-10-29 09:25:45.143 [WARN ] [home.internal.handler.ESPHomeHandler] - [esph-office] Ping responses lacking. Waited 4 times 10 seconds, total of 40. Assuming connection lost and disconnecting
2024-10-29 09:25:45.143 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-office] Disconnecting socket.
2024-10-29 09:25:45.144 [WARN ] [home.internal.handler.ESPHomeHandler] - [esph-lr-velux] Ping responses lacking. Waited 4 times 10 seconds, total of 40. Assuming connection lost and disconnecting
2024-10-29 09:25:45.144 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-lr-velux] Disconnecting socket.
2024-10-29 09:25:45.145 [WARN ] [home.internal.handler.ESPHomeHandler] - [esph-kitchen-shade-left] Ping responses lacking. Waited 4 times 10 seconds, total of 40. Assuming connection lost and disconnecting
2024-10-29 09:25:45.145 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-kitchen-shade-left] Disconnecting socket.
2024-10-29 09:25:45.146 [WARN ] [home.internal.handler.ESPHomeHandler] - [esph-kitchen-shade-right] Ping responses lacking. Waited 4 times 10 seconds, total of 40. Assuming connection lost and disconnecting
2024-10-29 09:25:45.146 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-kitchen-shade-right] Disconnecting socket.
==> /var/log/openhab/events.log <==
2024-10-29 09:25:45.144 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-office' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-29 09:25:45.145 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-lr-velux' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-29 09:25:45.146 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-left' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay
2024-10-29 09:25:45.147 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'esphome:device:esph-kitchen-shade-right' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): ESPHome did not respond to ping requests. 4 pings sent with 10 s delay

Note the time of the last “cannot connect”: 2024-10-29 09:25:45.147
The logs below show a successful connection at 2024-10-29 09:25:55.954

After that, the logs show what looks like a clean connect and discovery:

2024-10-29 09:25:55.634 [INFO ] [home.internal.handler.ESPHomeHandler] - [esph-office] Trying to connect to esph-office.some.domain:6053
2024-10-29 09:25:55.642 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-office] Opening socket to esph-office.some.domain at port 6053.
2024-10-29 09:25:55.643 [INFO ] [home.internal.handler.ESPHomeHandler] - [esph-lr-velux] Trying to connect to esph-lr-velux.some.domain:6053
2024-10-29 09:25:55.651 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-lr-velux] Opening socket to esph-lr-velux.some.domain at port 6053.
2024-10-29 09:25:55.652 [INFO ] [home.internal.handler.ESPHomeHandler] - [esph-kitchen-shade-left] Trying to connect to esph-kitchen-shade-left.some.domain:6053
2024-10-29 09:25:55.659 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-kitchen-shade-left] Opening socket to esph-kitchen-shade-left.some.domain at port 6053.
2024-10-29 09:25:55.659 [INFO ] [home.internal.handler.ESPHomeHandler] - [esph-kitchen-shade-right] Trying to connect to esph-kitchen-shade-right.some.domain:6053
2024-10-29 09:25:55.673 [INFO ] [home.internal.comm.ESPHomeConnection] - [esph-kitchen-shade-right] Opening socket to esph-kitchen-shade-right.some.domain at port 6053.
2024-10-29 09:25:55.954 [DEBUG] [home.internal.handler.ESPHomeHandler] - [esph-office] Connection established
2024-10-29 09:25:55.955 [DEBUG] [me.internal.comm.AbstractFrameHelper] - [esph-office] Sending message type HelloRequest with content 'client_info: "openHAB"
api_version_major: 1
api_version_minor: 9'
2024-10-29 09:25:55.963 [DEBUG] [home.internal.handler.ESPHomeHandler] - [esph-office] Received hello response api_version_major: 1
api_version_minor: 10
server_info: "esph-office (esphome v2024.9.2)"
name: "esph-office"
... some more

seime · October 29, 2024, 12:21pm

I would need a full log from OH startup until the first thing goes offline. I’m trying to rule out a possible threadpool starvation issue. The error message says “Ping responses lacking”, so I need to verify that pings are actually sent

seime · October 30, 2024, 8:01pm

@Will I’ve been debugging a bit with @Pedro_Liberal, and it seems like the openhab thinghandler threadpool gets starved, leading to pings not being sent as scheduled.

Can you try to increase the threadpool size?

In services/runtime.cfg add this line:
org.openhab.threadpool:thingHandler = 50

Also, if you are not using the Uptime Sensor — ESPHome please add it and monitor ESP devices for reboots - they do reboot every now and then.