home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.43k stars 30.67k forks source link

ESPHome entities constantly disconnecting #36011

Closed picto3000 closed 4 years ago

picto3000 commented 4 years ago

The problem

For a couple of weeks all ESPHome devices are randomly disconnecting, causing:

Looking into the logs, device pings appear to be failing and HA disconnects the device, only to rediscover the device almost instantaneously.

Occurring on a range of ESPhome devices:

Historically I've seen similar behaviour caused by custom_components, but none are installed and have reduced my setup complexity to remove possible component interference. All with no change.

Environment

Problem-relevant configuration.yaml

N/A

Traceback/Error logs

today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.88
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.87
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.84
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.86
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.80
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.83
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:25 PM 2020-05-23 14:25:45 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:27 PM 2020-05-23 14:27:50 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.84: Ping Failed!
today at 2:27 PM 2020-05-23 14:27:50 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.84
today at 2:27 PM 2020-05-23 14:27:50 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.84: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:27 PM 2020-05-23 14:27:52 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.84
today at 2:27 PM 2020-05-23 14:27:52 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.84
today at 2:29 PM 2020-05-23 14:29:51 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Ping Failed!
today at 2:29 PM 2020-05-23 14:29:51 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.87
today at 2:29 PM 2020-05-23 14:29:51 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:29 PM 2020-05-23 14:29:51 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.87
today at 2:30 PM 2020-05-23 14:30:26 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Ping Failed!
today at 2:30 PM 2020-05-23 14:30:26 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.87
today at 2:30 PM 2020-05-23 14:30:26 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:30 PM 2020-05-23 14:30:26 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.87
today at 2:30 PM 2020-05-23 14:30:46 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Ping Failed!
today at 2:30 PM 2020-05-23 14:30:46 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.87
today at 2:30 PM 2020-05-23 14:30:46 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:30 PM 2020-05-23 14:30:46 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.87
today at 2:30 PM 2020-05-23 14:30:51 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Ping Failed!
today at 2:30 PM 2020-05-23 14:30:51 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.88
today at 2:30 PM 2020-05-23 14:30:51 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:30 PM 2020-05-23 14:30:51 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.88
today at 2:31 PM 2020-05-23 14:31:01 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:31 PM 2020-05-23 14:31:01 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.88
today at 2:31 PM 2020-05-23 14:31:06 INFO (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for 192.168.1.88: Timeout while waiting for API response!
today at 2:31 PM 2020-05-23 14:31:06 INFO (MainThread) [homeassistant.components.esphome] Trying to reconnect in 2 seconds
today at 2:31 PM 2020-05-23 14:31:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:31 PM 2020-05-23 14:31:08 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.88
today at 2:32 PM 2020-05-23 14:32:43 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Ping Failed!
today at 2:32 PM 2020-05-23 14:32:43 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.88
today at 2:32 PM 2020-05-23 14:32:43 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:32 PM 2020-05-23 14:32:48 INFO (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for 192.168.1.88: Timeout while waiting for API response!
today at 2:32 PM 2020-05-23 14:32:48 INFO (MainThread) [homeassistant.components.esphome] Trying to reconnect in 2 seconds
today at 2:32 PM 2020-05-23 14:32:48 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:32 PM 2020-05-23 14:32:50 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.88
today at 2:33 PM 2020-05-23 14:33:05 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Error while reading incoming messages: Error while receiving data: [Errno 104] Connection reset by peer
today at 2:33 PM 2020-05-23 14:33:05 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.88
today at 2:33 PM 2020-05-23 14:33:05 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.88
today at 2:33 PM 2020-05-23 14:33:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Ping Failed!
today at 2:33 PM 2020-05-23 14:33:06 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.87
today at 2:33 PM 2020-05-23 14:33:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.87: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:33 PM 2020-05-23 14:33:06 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.87
today at 2:33 PM 2020-05-23 14:33:10 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.88: Ping Failed!
today at 2:34 PM 2020-05-23 14:34:36 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Ping Failed!
today at 2:34 PM 2020-05-23 14:34:36 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.82
today at 2:34 PM 2020-05-23 14:34:36 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:34 PM 2020-05-23 14:34:36 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:34 PM 2020-05-23 14:34:36 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:37 PM 2020-05-23 14:37:36 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.83: Ping Failed!
today at 2:37 PM 2020-05-23 14:37:36 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.83
today at 2:37 PM 2020-05-23 14:37:36 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.83: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:37 PM 2020-05-23 14:37:52 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.83
today at 2:38 PM 2020-05-23 14:38:26 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Ping Failed!
today at 2:38 PM 2020-05-23 14:38:26 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.82
today at 2:38 PM 2020-05-23 14:38:26 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:38 PM 2020-05-23 14:38:26 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:39 PM 2020-05-23 14:39:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.80: Ping Failed!
today at 2:39 PM 2020-05-23 14:39:06 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.80
today at 2:39 PM 2020-05-23 14:39:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.80: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:39 PM 2020-05-23 14:39:06 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.80
today at 2:40 PM 2020-05-23 14:40:16 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Ping Failed!
today at 2:40 PM 2020-05-23 14:40:16 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.82
today at 2:40 PM 2020-05-23 14:40:16 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:40 PM 2020-05-23 14:40:16 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:40 PM 2020-05-23 14:40:16 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82
today at 2:43 PM 2020-05-23 14:43:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Ping Failed!
today at 2:43 PM 2020-05-23 14:43:06 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.82
today at 2:43 PM 2020-05-23 14:43:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.82: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:43 PM 2020-05-23 14:43:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.86: Ping Failed!
today at 2:43 PM 2020-05-23 14:43:06 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for 192.168.1.86
today at 2:43 PM 2020-05-23 14:43:06 INFO (MainThread) [aioesphomeapi.connection] 192.168.1.86: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
today at 2:43 PM 2020-05-23 14:43:07 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.86
today at 2:43 PM 2020-05-23 14:43:07 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to 192.168.1.82

Example Kogan Smart Plug ESPHome YAML - all yamls are very similar:

esphome:
  name: $hostname
  comment: $comment
  platform: ESP8266
  board: esp8285

#CUSTOMISATIONS
substitutions:
  hostname: "kogan_kpmu_01" #Internal designated name
  comment: "Laundry - Tumble Dryer" #Usually what it's currently used for
  device: "kogan_kpmu_01" #What device is connected/controlled?
  icon: "mdi:power-socket-au" #MDI device icon e.g. mdi:power-socket-au via https://materialdesignicons.com
  restore_mode: "restore_default_on" #Power auto on with reboot? e.g. restore_default_on or ALWAYS_OFF
  ip: "192.168.1.83" #Static IP address
  old_ip: "192.168.1.141" #used when swaping static IPs

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_pwd
#  use_address: "$old_ip" #sonoff_04.local
  manual_ip:
    static_ip: "$ip"
    gateway: !secret gateway
    subnet: !secret subnet

logger:
api:
ota:
# web_server:
#   port: 80

binary_sensor:
  - platform: gpio
    id: toggle
    pin:
      number: GPIO0
      mode: INPUT_PULLUP
      inverted: true
    internal: true
    on_press:
      then:
        - switch.toggle: relay

  - platform: status
    name: "$hostname Status"

switch:
  - platform: gpio
    id: led
    pin:
      number: GPIO13
      inverted: true
#    restore_mode: ALWAYS_OFF

  - platform: gpio
    name: "$device"
    pin: GPIO14
    id: relay
    icon: "$icon"
    restore_mode: "$restore_mode"

sensor:
  - platform: hlw8012
    sel_pin:
      number: GPIO12
      inverted: true
    cf_pin: GPIO04
    cf1_pin: GPIO05
    current:
      name: "$device Current"
      unit_of_measurement: A
    voltage:
      name: "$device Voltage"
      unit_of_measurement: V
    power:
      id: ${device}_wattage
      name: "$device Power"
      unit_of_measurement: W
    current_resistor: 0.00215
    voltage_divider: 799
    change_mode_every: 8
    update_interval: 5s

  - platform: total_daily_energy
    name: "$device Daily Energy"
    power_id: ${device}_wattage
    filters:
      - multiply: 0.001
    unit_of_measurement: kWh

  - platform: uptime
    name: "Uptime $hostname"
    id: uptime_s
    update_interval: 60s

time:
  - platform: homeassistant
    id: homeassistant_time

text_sensor:
  - platform: template
    name: "$hostname Uptime (formatted)"
    lambda: |-
      uint32_t dur = id(uptime_s).state;
      int dys = 0;
      int hrs = 0;
      int mnts = 0;
      if (dur > 86399) {
        dys = trunc(dur / 86400);
        dur = dur - (dys * 86400);
      }
      if (dur > 3599) {
        hrs = trunc(dur / 3600);
        dur = dur - (hrs * 3600);
      }
      if (dur > 59) {
        mnts = trunc(dur / 60);
        dur = dur - (mnts * 60);
      }
      char buffer[17];
      sprintf(buffer, "%ud %02uh %02um %02us", dys, hrs, mnts, dur);
      return {buffer};
    icon: mdi:clock-start
    update_interval: 60s    

Additional information

I see #35540 but this appears to be unrelated. Different log issues.

probot-home-assistant[bot] commented 4 years ago

esphome documentation esphome source (message by IssueLinks)

probot-home-assistant[bot] commented 4 years ago

Hey there @OttoWinter, mind taking a look at this issue as its been labeled with a integration (esphome) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

picto3000 commented 4 years ago

An update that 0.110.2 has helped the situation. Logs are still showing failed pings and disconnects, Logbook are showing devices going unavailable and disconnecting/reconnecting, but the devices uptime counters are no longer resetting and switches are no longer momentarily switching off/on.

ronytomen commented 4 years ago

I had a similar issues in the past:

  1. 2.4 GHz network needed to be isolated because of congestion and overlap with neighbors. This one just started happening on day, luckily it did not correspond with an upgrade or other change to the system.
  2. On ESP32 devices where I was doing Bluetooth Low Energy (BLE) scanning there were major issues with timing of WiFi and Bluetooth which resulted in those devices dropping off the network. There has been a lot of discussions around this issue. I resolved it for my main BLE scanner by moving to the ESP32 module with Ethernet to remove WiFi from the equation.

What do the logs on the ESPHome device tell you?

picto3000 commented 4 years ago

As of 0.110.4 the unavailable/available Logbook entries have stopped. HA logs are not showing any failed pings or disconnects.

I had a similar issues in the past:

  1. 2.4 GHz network needed to be isolated because of congestion and overlap with neighbors. This one just started happening on day, luckily it did not correspond with an upgrade or other change to the system.
  2. On ESP32 devices where I was doing Bluetooth Low Energy (BLE) scanning there were major issues with timing of WiFi and Bluetooth which resulted in those devices dropping off the network. There has been a lot of discussions around this issue. I resolved it for my main BLE scanner by moving to the ESP32 module with Ethernet to remove WiFi from the equation.

What do the logs on the ESPHome device tell you?

I've been managing 2.4Ghz WiFi congestion by making sure an unused band is being used. Overall I don't have much 2.4Ghz congestion.

None of my ESP devices have Bluetooth. I do use mitemp_bt BLE sensors, which are polled by HA using my NUC's BT, but as part of my testing I disable this integration and the issue still remained.

ryanjohnsontv commented 4 years ago

In several of my devices I've had to add this to the logger component, and doing so stopped the exact same issues that you seem to be experiencing:

logger:
  baud_rate: 0
laca75tn commented 4 years ago

Thanks for posting your solution. How is that fixing the problem?

picto3000 commented 4 years ago

This has now come back without upgrading HA, and I now suspect the issue is devices rebooting. I'll open a ticket with ESPHome but won't close this just yet.

In several of my devices I've had to add this to the logger component, and doing so stopped the exact same issues that you seem to be experiencing:

logger:
  baud_rate: 0

This has no affect.

stale[bot] commented 4 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

Lepelot commented 2 years ago

I don't know if this issue has been resolved, but I am experiencing it right no with mini switches and I relay board I purchased recently (ATHOM with ESPHome installed). Isolating the 2.4GHz wifi network seem to improve the situation, but they are still disconnecting randomely.