core: Intermittent connection issues with ESP Home devices with bk72xx

The problem

I am getting Intermittent connection issues when connecting home assistant to a esphome light device.

When it connects and run, it runs perfectly well.

It disconnects around 2-3 mins of usage and tries to reconnect after losing al control. The state gets stuck and you can’t turn on/off or control the color until the reconnect.

This happens very frequently and I’m not sure what the cause is. I attached the logs below and assumed that it might have been something with the aioesphomeapi.

What I’ve noticed is that the web_service connection for the esphome light still works and is able to still function with the REST API. This REST API doesn’t go down but the HA => ESPHome connect/disconnect frequently. (2-3min intervals)

This thread is very similar to my problem. https://community.home-assistant.io/t/esphome-didnt-respond-to-ping-request-in-time-disconnecting/608538

Any help or information is appreciated.

What version of Home Assistant Core has the issue?

core-2023.9.3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

esphome

Link to integration documentation on our website

https://www.home-assistant.io/integrations/esphome/

Diagnostics information

2023-09-30 15:33:16.406 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:35:46.643 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:38:16.889 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:40:47.138 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:43:17.413 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:45:47.689 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:48:17.923 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:50:48.163 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:53:18.401 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:56:28.468 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: Ping response not received after 90.0 seconds 2023-09-30 15:57:41.102 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true

2023-09-30 15:57:41.102 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0007200d23f05c731001 2023-09-30 15:57:43.875 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true state: true has_brightness: true brightness: 0.509803951 has_color_mode: true color_mode: 19

2023-09-30 15:57:43.876 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0016200d23f05c731001180120012d8382023fb00101b80113 2023-09-30 15:57:46.228 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Got message of type LightStateResponse: key: 1935470627 brightness: 1 color_mode: 19 color_brightness: 1 red: 1 green: 1 blue: 1 white: 1 color_temperature: 153.846161 cold_white: 1 warm_white: 1

2023-09-30 15:57:46.228 DEBUG (MainThread) [homeassistant.components.esphome.entry_data] tuya-recessed-light-01: dispatching update with key 1935470627: LightState(key=1935470627, state=False, brightness=1.0, color_mode=19, color_brightness=1.0, red=1.0, green=1.0, blue=1.0, white=1.0, color_temperature=153.8462, cold_white=1.0, warm_white=1.0, effect=‘’) 2023-09-30 15:57:49.383 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Got message of type LightStateResponse: key: 1935470627 state: true brightness: 1 color_mode: 19 color_brightness: 1 red: 1 green: 1 blue: 1 white: 1 color_temperature: 153.846161 cold_white: 1 warm_white: 1

2023-09-30 15:57:49.383 DEBUG (MainThread) [homeassistant.components.esphome.entry_data] tuya-recessed-light-01: dispatching update with key 1935470627: LightState(key=1935470627, state=True, brightness=1.0, color_mode=19, color_brightness=1.0, red=1.0, green=1.0, blue=1.0, white=1.0, color_temperature=153.8462, cold_white=1.0, warm_white=1.0, effect=‘’) 2023-09-30 15:57:53.523 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true state: true has_color_mode: true color_mode: 35 has_color_brightness: true color_brightness: 1 has_rgb: true red: 1 green: 0.0196078438 blue: 0.0352941193

2023-09-30 15:57:53.523 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0029200d23f05c731001180130013d0000803f45a1a0a03c4d9190103da00101ad010000803fb00101b80123 2023-09-30 15:57:55.760 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true state: true has_color_mode: true color_mode: 35 has_color_brightness: true color_brightness: 1 has_rgb: true red: 0.662745118 green: 1 blue: 0.0392156877

2023-09-30 15:57:55.760 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0029200d23f05c731001180130013daaa9293f450000803f4da1a0203da00101ad010000803fb00101b80123 2023-09-30 15:58:09.583 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true state: true has_color_mode: true color_mode: 35 has_color_brightness: true color_brightness: 1 has_rgb: true red: 0.109803922 green: 0.388235301 blue: 1

2023-09-30 15:58:09.583 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0029200d23f05c731001180130013de1e0e03d45c7c6c63e4d0000803fa00101ad010000803fb00101b80123 2023-09-30 15:58:15.892 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true state: true has_color_mode: true color_mode: 35 has_color_brightness: true color_brightness: 1 has_rgb: true red: 1 green: 0.0274509806 blue: 0.109803922

2023-09-30 15:58:15.892 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0029200d23f05c731001180130013d0000803f45e1e0e03c4de1e0e03da00101ad010000803fb00101b80123 2023-09-30 15:58:17.812 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending LightCommandRequest: key: 1935470627 has_state: true state: true has_color_mode: true color_mode: 35 has_color_brightness: true color_brightness: 1 has_rgb: true red: 1 green: 0.117647059 blue: 0.149019614

2023-09-30 15:58:17.812 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 0029200d23f05c731001180130013d0000803f45f1f0f03d4d9998183ea00101ad010000803fb00101b80123 2023-09-30 15:58:28.535 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending PingRequest: 2023-09-30 15:58:28.535 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 000007 2023-09-30 15:58:48.537 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending PingRequest: 2023-09-30 15:58:48.537 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 000007 2023-09-30 15:58:48.537 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: PingResponse (pong) was not received since last keep alive after 20.0 seconds; rescheduling keep alive 2023-09-30 15:58:58.705 WARNING (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connection error occurred: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:58:58.706 DEBUG (MainThread) [aioesphomeapi.connection] Cleaning up connection to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:58:58.706 DEBUG (MainThread) [aioesphomeapi.connection] Cleaning up connection to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:58:58.706 INFO (MainThread) [aioesphomeapi.reconnect_logic] Processing unexpected disconnect from ESPHome API for tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:58:58.706 DEBUG (MainThread) [homeassistant.components.esphome.manager] tuya-recessed-light-01: 192.168.2.38 disconnected (expected=False), running disconnected callbacks 2023-09-30 15:58:58.708 DEBUG (MainThread) [aioesphomeapi.reconnect_logic] Trying to connect to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:58:58.708 DEBUG (MainThread) [aioesphomeapi.reconnect_logic] Connected lock acquired for tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:58:58.709 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Connecting to 192.168.2.38:6053 (AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address=‘192.168.2.38’, port=6053))) 2023-09-30 15:58:58.713 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Opened socket to 192.168.2.38:6053 (AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address=‘192.168.2.38’, port=6053))) 2023-09-30 15:58:58.714 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending HelloRequest: client_info: “Home Assistant 2023.9.3” api_version_major: 1 api_version_minor: 9

2023-09-30 15:58:58.714 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 001d010a17486f6d6520417373697374616e7420323032332e392e3310011809 2023-09-30 15:58:58.751 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Got message of type HelloResponse: api_version_major: 1 api_version_minor: 9 server_info: “tuya-recessed-light-01 (esphome v2023.9.1)” name: “tuya-recessed-light-01”

2023-09-30 15:58:58.751 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Successfully connected (‘tuya-recessed-light-01 (esphome v2023.9.1)’ API=1.9) 2023-09-30 15:58:58.751 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending ConnectRequest: 2023-09-30 15:58:58.751 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 000003 2023-09-30 15:58:58.774 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Got message of type ConnectResponse: 2023-09-30 15:58:58.775 INFO (MainThread) [aioesphomeapi.reconnect_logic] Successfully connected to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:58:58.775 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending DeviceInfoRequest: 2023-09-30 15:58:58.775 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 000009 2023-09-30 15:59:08.776 WARNING (MainThread) [homeassistant.components.esphome.manager] Error getting device info for 192.168.2.38: Timeout waiting for response for <class ‘api_pb2.DeviceInfoRequest’> after 10.0s 2023-09-30 15:59:08.778 DEBUG (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Sending DisconnectRequest: 2023-09-30 15:59:08.778 DEBUG (MainThread) [aioesphomeapi._frame_helper.plain_text] tuya-recessed-light-01 @ 192.168.2.38: Sending plaintext frame 000005 2023-09-30 15:59:08.789 DEBUG (MainThread) [aioesphomeapi.connection] Cleaning up connection to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:59:08.790 ERROR (MainThread) [aioesphomeapi.connection] tuya-recessed-light-01 @ 192.168.2.38: Failed to send disconnect request: tuya-recessed-light-01 @ 192.168.2.38: EOF received 2023-09-30 15:59:08.792 DEBUG (MainThread) [aioesphomeapi.connection] Cleaning up connection to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:59:08.792 DEBUG (MainThread) [aioesphomeapi.connection] Cleaning up connection to tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:59:08.792 INFO (MainThread) [aioesphomeapi.reconnect_logic] Processing expected disconnect from ESPHome API for tuya-recessed-light-01 @ 192.168.2.38 2023-09-30 15:59:08.792 DEBUG (MainThread) [homeassistant.components.esphome.manager] tuya-recessed-light-01: 192.168.2.38 disconnected (expected=True), running disconnected callbacks 2023-09-30 15:59:08.792 DEBUG (MainThread) [aioesphomeapi.reconnect_logic] Scheduling new connect attempt in 5.000000 seconds

Example YAML snippet

No response

Anything in the logs that might be useful for us?

From the esp logger:

[14:47:54][D][api:102]: Accepted 192.168.3.1
[14:47:54][D][api.connection:1031]: Home Assistant 2023.9.3 (192.168.3.1): Connected successfully
[14:48:08][D][light:036]: 'Light' Setting:
[14:48:08][D][light:041]:   Color mode: Cold/warm white
[14:48:08][D][light:047]:   State: ON
[14:48:08][D][light:085]:   Transition length: 1.0s
[14:49:38][D][light:036]: 'Light' Setting:
[14:49:38][D][light:047]:   State: OFF
[14:49:38][D][light:085]:   Transition length: 1.0s
[14:50:38][W][api.connection:117]: Home Assistant 2023.9.3 (192.168.3.1) didn't respond to ping request in time. Disconnecting...
[14:50:38][D][api:102]: Accepted 192.168.3.1
[14:50:38][D][api.connection:1031]: Home Assistant 2023.9.3 (192.168.3.1): Connected successfully
WARNING 192.168.2.38: Connection error occurred: EOF received
INFO Processing unexpected disconnect from ESPHome API for 192.168.2.38
WARNING Disconnected from API
INFO Successfully connected to 192.168.2.38
[14:52:33][I][ota:117]: Boot seems successful, resetting boot loop counter.
[14:52:33][D][lt.preferences:104]: Saving 1 preferences to flash...
[14:52:33][D][lt.preferences:132]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
[14:53:08][W][api.connection:117]: Home Assistant 2023.9.3 (192.168.3.1) didn't respond to ping request in time. Disconnecting...
[14:53:08][D][api:102]: Accepted 192.168.3.1
[14:53:08][D][api.connection:1031]: Home Assistant 2023.9.3 (192.168.3.1): Connected successfully
[14:53:13][D][light:036]: 'Light' Setting:
[14:53:13][D][light:041]:   Color mode: RGB
[14:53:16][D][light:036]: 'Light' Setting:
WARNING 192.168.2.38: Connection error occurred: EOF received

Additional information

No response

About this issue

  • Original URL
  • State: closed
  • Created 9 months ago
  • Comments: 16 (9 by maintainers)

Commits related to this issue

Most upvoted comments

I dug through the esphome api code quite a bit and could not find a path where the ping would not be responded to. I think this is a problem with the device not receiving the ping response because of a network issue or it’s a bug in the esphome device code where it isn’t processing the incoming api traffic (seems unlikely if the web server is responding)

I refactored the library to have a single incoming packet processor dispatch path in https://github.com/esphome/aioesphomeapi/releases/tag/v18.0.10 just to be sure it’s not the library and still couldn’t reproduce the issue

This is almost certainly an issue with ESPHome itself

Unfortunately its not possible to transfer this issue.

Please continue at https://github.com/esphome/issues/issues/new?assignees=&labels=&projects=&template=bug_report.yml