Recurring connection errors

jhemak commented 2 weeks ago

Troubleshooting Guide

[X] I have followed the steps in the troubleshooting guide and my issue is either not listed or is not solved.

Description

Hello, over the past couple weeks I have started to see errors like this in my log. Any idea what may cause or fix it?

2024-09-02 10:16:42.686 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky @ IP: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-02 10:17:46.818 WARNING (MainThread) [homeassistant.components.esphome.manager] Error getting setting up connection for IP: Timeout waiting for ListEntitiesDoneResponse, ListEntitiesAlarmControlPanelResponse, ListEntitiesBinarySensorResponse, ListEntitiesButtonResponse, ListEntitiesCameraResponse, ListEntitiesClimateResponse, ListEntitiesCoverResponse, ListEntitiesDateResponse, ListEntitiesDateTimeResponse, ListEntitiesEventResponse, ListEntitiesFanResponse, ListEntitiesLightResponse, ListEntitiesLockResponse, ListEntitiesMediaPlayerResponse, ListEntitiesNumberResponse, ListEntitiesSelectResponse, ListEntitiesSensorResponse, ListEntitiesServicesResponse, ListEntitiesSirenResponse, ListEntitiesSwitchResponse, ListEntitiesTextResponse, ListEntitiesTextSensorResponse, ListEntitiesTimeResponse, ListEntitiesUpdateResponse, ListEntitiesValveResponse after 60s
2024-09-02 10:17:56.820 ERROR (MainThread) [aioesphomeapi.connection] upsy-desky@IP: disconnect request failed: Timeout waiting for DisconnectResponse after 10.0s

Logs

No response

Which version of the Upsy Desky firmware config are you running?

4.0.0

How do you manage your Upsy Desky's updates?

OTA Updates

If you're using an ESPHome YAML config, which version of ESPHome are you running?

No response

ESPHome Config

No response

tjhorner commented 2 weeks ago

Are these errors being manifested through any symptoms like unavailable or unknown sensors?

jhemak commented 2 weeks ago

Yes, I believe so. The sensors go unavailable around the same time and then unknown a few minutes later.

jhemak commented 2 weeks ago

OK ... just confirmed... when this error occurs in the logs, all sensors in the UI go unavailable. A few minutes later, some sensors go to unknown (e.g. preset_1) and others go to their actual values (e.g. max_target_height).

tjhorner commented 2 weeks ago

Thanks for confirming. I'm interested to know the following:

How often does this occur?
What desk model do you have?
Are you powering the Upsy Desky directly from the desk or with a USB-C power supply?

jhemak commented 2 weeks ago

It seems to happen a handful of times per day. I'll try to keep better track over the next few days and let you know.

I have an Uplift v2. I've had all this going for several months now but don't think I was getting this error until the past 30 days or so.

Currently powering the board directly from the desk but have tried a separate USB-C power supply over the past few days. At first I thought that had fixed it, but after some time the errors resumed so I'm not sure it had any effect (hard to say, since it's inconsistent.) I currently have USB-C disconnected (and also haven't seen the error since my message ~5 hours ago ... but I'm sure it will be back!)

jhemak commented 2 weeks ago

OK - the answer is that this is happening quite often. Here are some times from error to sensor recovery from just 10 hours today:

6:36:43 -> 6:36:57 9:25:06 -> 9:26:04 11:33:52 -> 11:33:59 1:11:25 -> 1:11:55 1:18:05 -> 1:19:23 1:35:47 -> 1:36:57 1:43:39 -> 1:44:22 1:57:19 -> 1:57:34 2:07:33 -> 2:09:34 2:28:21 -> 2:29:49 3:02:24 -> 3:03:31 3:11:12 -> 3:12:58 3:30:50 -> 3:31:07 3:43:33 -> 3:44:00 3:58:55 -> 3:59:33

And here are the actual log messages:

2024-09-02 14:39:45.759 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-02 14:39:48.829 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Error connecting to [AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address='X.X.X.X', port=6053))]: [Errno 113] Connect call failed ('X.X.X.X', 6053) (SocketAPIError)
2024-09-03 06:36:43.858 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 06:36:53.689 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: upsy-desky-xxxxxx @ X.X.X.X: The connection dropped immediately after encrypted hello; Try enabling encryption on the device or turning off encryption on the client (Home Assistant 2024.8.3).
2024-09-03 06:36:53.690 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: upsy-desky-xxxxxx @ X.X.X.X: The connection dropped immediately after encrypted hello; Try enabling encryption on the device or turning off encryption on the client (Home Assistant 2024.8.3). (HandshakeAPIError)
2024-09-03 09:25:06.233 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 09:25:37.668 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Handshake timed out after 30.0s (TimeoutAPIError)
2024-09-03 09:25:37.669 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: upsy-desky-xxxxxx @ X.X.X.X: Connection lost
2024-09-03 11:33:52.270 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 13:11:25.845 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 13:11:28.924 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Error connecting to [AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address='X.X.X.X', port=6053))]: [Errno 113] Connect call failed ('X.X.X.X', 6053) (SocketAPIError)
2024-09-03 13:18:05.017 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 13:18:18.247 WARNING (MainThread) [homeassistant.components.esphome.manager] Error getting setting up connection for X.X.X.X: Timeout waiting for DeviceInfoResponse after 10.0s
2024-09-03 13:18:28.250 ERROR (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: disconnect request failed: Timeout waiting for DisconnectResponse after 10.0s
2024-09-03 13:35:47.042 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 13:36:46.219 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Timeout waiting for HelloResponse, ConnectResponse after 30.0s (TimeoutAPIError)
2024-09-03 13:36:46.220 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: upsy-desky-xxxxxx @ X.X.X.X: Connection lost
2024-09-03 13:43:39.843 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 13:57:19.469 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 14:07:33.581 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 14:08:05.814 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Handshake timed out after 30.0s (TimeoutAPIError)
2024-09-03 14:08:05.815 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: upsy-desky-xxxxxx @ X.X.X.X: Connection lost
2024-09-03 14:28:21.833 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 14:28:57.970 WARNING (MainThread) [homeassistant.components.esphome.manager] Error getting setting up connection for X.X.X.X: Timeout waiting for DeviceInfoResponse after 10.0s
2024-09-03 14:29:07.972 ERROR (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: disconnect request failed: Timeout waiting for DisconnectResponse after 10.0s
2024-09-03 15:02:24.464 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 15:11:12.519 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 15:11:43.511 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Handshake timed out after 30.0s (TimeoutAPIError)
2024-09-03 15:11:43.512 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: upsy-desky-xxxxxx @ X.X.X.X: Connection lost
2024-09-03 15:12:15.322 WARNING (MainThread) [homeassistant.components.esphome.manager] Error getting setting up connection for X.X.X.X: Timeout waiting for DeviceInfoResponse after 10.0s
2024-09-03 15:12:25.325 ERROR (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: disconnect request failed: Timeout waiting for DisconnectResponse after 10.0s
2024-09-03 15:30:50.351 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 15:43:33.932 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds
2024-09-03 15:43:36.988 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for upsy-desky-xxxxxx @ X.X.X.X: Error connecting to [AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address='X.X.X.X', port=6053))]: [Errno 113] Connect call failed ('X.X.X.X', 6053) (SocketAPIError)
2024-09-03 15:58:55.062 WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ X.X.X.X: Connection error occurred: Ping response not received after 90.0 seconds

And here is my config:

substitutions:
  name: upsy-desky-xxx
  friendly_name: Upsy Desky xxx
packages:
  tj_horner.upsy_desky: github://tjhorner/upsy-desky/firmware/base.yaml@master
esphome:
  name: ${name}
  name_add_mac_suffix: false
  friendly_name: ${friendly_name}
api:
  encryption:
    key: xxx

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password

logger:
  level: INFO

ota:
  - platform: esphome
    password: ""

jhemak commented 1 week ago

Hi @tjhorner, I'm going to go ahead and say this must be a power issue after all. Right after I sent you the update yesterday I plugged the USB-C power back in and the errors have been gone for over 24 hours. Still seems strange that it started to be an issue all of a sudden after using it without the external power for many months.

jhemak commented 1 week ago

Ugh - just kidding. I am continuing to see various errors like the ones above even with the USB power plugged in. Can't seem to find any pattern to why and when they pop up. However, I get no errors from my Bluetooth proxy, so it seems unique to this device for some reason. Any ideas?

tjhorner commented 1 week ago

Something I'd like to try is collecting logs via USB - this will let us know if it's a true connection issue or if it's crashing for some reason. The easiest way to get logs via USB is through this page: https://upsy-desky.tjhorner.dev/docs/troubleshooting/#collecting-logs

Keep that open until the device disconnects again, then you can save the logs for inspection.

jhemak commented 1 week ago

So I'm not positive I am doing this right... but for the past 24 hours, the only error showing up in the USB log is

Terminal disconnected: BufferOverrunError: Buffer overrun

And in the HA log, I see

WARNING (MainThread) [aioesphomeapi.connection] upsy-desky-xxxxxx @ xxx.xxx.xxx.xxx: Connection error occurred: [Errno 104] Connection reset by peer

This is the only error I've been seeing now... not the ones mentioned above.

tjhorner / upsy-desky