Intermittent connection issues with ESP Home devices with bk72xx #101174
Comments
|
Hey there @OttoWinter, @jesserockz, @kbx81, @bdraco, mind taking a look at this issue as it has been labeled with an integration ( Code owner commandsCode owners of
(message by CodeOwnersMention) esphome documentation |
|
Do you have noise encryption turned on? |
|
In the logs above I turned it off. I used the following esp yaml to create the firmware. |
|
Does it make any difference if you have encryption on or off? |
|
Nothing changed when I turned it on and off. The device gets "stuck" after putting in a few commands and seemly restarts. It also has a tendency to get stuck when I don't use it for a while. Its hard for me to determine as the logs on the device don't show any more info. Whats weird is that I can use the device when its stuck on HA with the rest api so my thought process is that something is happening with aioesphomeapi? Do you happen to know if theres a way I can pull out more logs anywhere? Maybe I missed something. There is one more thing that might be related. The device that I'm flashing was just supported using the Libre Tiny lib that was merged into esphome as of the latest release 2023.9.1 and the chip is the bk7231n. Not sure if that helps. |
|
Two questions:
|
|
To answer the questions above.
I'm open to suggestions on how we can probe this thing more. Currently stuck :( |
|
Might be a bit of a silly question, but have you ruled out an IP conflict? On the rare occasion that I see constant disconnects of the API like this, I usually suspect some type of networking issue, be it an IP conflict that I didn't realize, a signal strength issue or some other infrastructure-related issue going on that's causing connections to break. I don't know your background or what you have/haven't tried so far, but I'll toss out some suggestions... Since you have manually configured the IP here, I think the way I would troubleshoot this would be:
I know you mentioned that you're suspicious of aioesphomeapi, but I don't think that's the issue here, as basically anything and everything ESPHome funnels through that and, if it were broken, I have to expect that we would be hearing a lot more noise from a lot of other folks...myself among them. I've got almost 60 ESPHome devices on my home network here and I never have issues like what you're reporting here. 😇 |
|
I'd also be interested to know what hardware you are running your HA instance on as well as what sits between it and your ESPHome device(s) infrastructure-wise. |
|
So originally I had the devices pull the ip via DHCP originally and it was having the issues I indicated above. Currently my test devices are next to the AP, so I can rule out signal strength too. I checked the ARP tables and there isn't any conflicts for ip either. I know none of this is helpful, but something worth noting is that I can't seem to get OTA updates working. I wanted to disable the web_service on the firmware to see if it was a memory issue, but I haven't been able to do that since I'd like a way to revert if things don't pan out. 🤔 |
|
What do you have the minimum data rate set to on your wifi access point? |
|
I haven't changed anything so i believe it is set to 6mbps by default. |
|
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 |
related issue #101174 (likely does not solve but reduces one path as a cause) changelog: esphome/aioesphomeapi@v18.0.9...v18.0.10
|
While I didn't see anything that will specifically fix the described issue, all the Even if it doesn't solve the problem, there is some more debug logging added that may hint at the source of the problem. |
|
Any further progress on this? I am running ESP Home 2023.11.6, and have 17 Tuya/Beken devices. They ALL give me the errors @TheAznShumai mentioned above. 6 are TreatLife dimmers, 2 TreatLife Fan controls, and the remaining are downlights. The downlights are the worst because as mentioned above they stop working when they are in this state so you are left with smart lights that will not turn off. Needless to say the Wife Acceptance Factor is dropping as the days move forward. Here is a config for one of my dimmers (I disabled substitutions:
device_description: Treatlife DS01C Dimmer - Beken 1.1.17
device_name: dimmer-wd04
device_friendly_name: Dimmer WD04
esphome:
name: $device_name
friendly_name: $device_friendly_name
comment: $device_description
bk72xx:
board: generic-bk7231t-qfn32-tuya
logger:
level: ERROR
baud_rate: 0
# web_server:
mdns:
api:
ota:
wifi:
ssid: !secret wifi_ssid
password: !secret wifi_password
ap:
ssid: $device_name
password: !secret wifi_ap_password
captive_portal:
uart:
rx_pin: RX1
tx_pin: TX1
baud_rate: 9600
tuya:
light:
- platform: "tuya"
id: light_1
name: "Dimmer"
switch_datapoint: 1
dimmer_datapoint: 2
min_value_datapoint: 3
min_value: 150
max_value: 1000Here are some log entries on the HA side I am trying to get a fresh log entry from the device itself (using |
bdraco
changed the title
|
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 |
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?
Additional information
No response
The text was updated successfully, but these errors were encountered: