search

esphome / issues

Issue Tracker for ESPHome
https://esphome.io/
290 stars 34 forks source link

Home Assistant API breaks when loop() slows down to slightly under 1 second #1383

Closed unbreakab1e closed 3 years ago

unbreakab1e commented 4 years ago

Operating environment/Installation (Hass.io/Docker/pip/etc.):

venv installation (python3.7) on MacOS 10.15.6

ESP (ESP32/ESP8266, Board/Sonoff):

Tested on ESP32 Devkit v1 and Wemos D1 Mini

ESPHome version (latest production, beta, dev branch)

1.14.5

Affected component:

Found the issue while implementing a Custom Component

Description of problem: As I mentioned earlier, I was tinkering with creating a Custom Component to control my boiler which uses OpenTherm for communications. I have an adapter board built and confirmed it is working with simple Arduino sketches both on Wemos D1 and Arduino UNO. For the OpenTherm library I opted for this one https://github.com/ihormelnyk/opentherm_library Due to the nature of OpenTherm protocol, each communication session with the boiler takes considerable amount of time and after raising logging to VERY_VERBOSE I can see a number of lines like this:

[22:19:27][V][app:076]: A component took a long time in a loop() cycle (2.03 s).

This would not bother me at all, but the problem is that under these circumstances Home Assistant Integration broke. I can discover new ESPHome device using mDNS or add it using hostname/ip address, but after the password entry device is added without any entities: no sensors, in this case. Home Assistant log shows lines like this:

Jul 29 22:12:34 hass hass[16578]: 2020-07-29 22:12:34 INFO (MainThread) [aioesphomeapi.connection] 172.16.1.119: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes

Removing all OpenTherm communication from the node got rid of this problem. Since I had some spare time I decided to check if I could reproduce the same behaviour without OpenTherm, so I started with a simple update() function with delay(1000) and gradually lowered to 937-954ms -- by this time I got bored of bisecting the value and compiling the firmware :) It is worth mentioning that MQTT on this node continues to work as intended and Home Assistant can discover node's entities via MQTT discovery topic, so for a while I resorted to MQTT as a workaround, but still having API working would be great.

Problem-relevant YAML-configuration entries:

esphome:
  name: thermostat
  platform: ESP32
  board: nodemcu-32s
  includes:
    - custom_components/opentherm_sensors.h
  libraries:
    - "../3d/opentherm_library"

wifi:
  ssid: !secret che6_wifi_ssid
  password: !secret che6_wifi_pass
  domain: !secret che6_wifi_domain
  ap:
    ssid: "Thermostat Fallback Hotspot"
    password: !secret fallback_ap_pass

captive_portal:

debug:

# Enable logging
logger:
  level: VERY_VERBOSE

ota:
  password: "<redacted>"

web_server:
  port: 80

time:
  - platform: sntp
    id: sntp_time
    servers:
      - 0.ru.pool.ntp.org
      - 1.ru.pool.ntp.org
      - 2.ru.pool.ntp.org

# Enable Home Assistant API
api:
  password: "<redacted>"
  reboot_timeout: 60min

custom_component:
- lambda: |-
    auto thermostat = new Thermostat();
    return {thermostat};

sensor:
- platform: custom
  lambda: |-
    auto thermostat_sensor = new ThermostatSensor();
    App.register_component(thermostat_sensor);
    return {
      thermostat_sensor->setpointSensor,
      thermostat_sensor->hotWaterTemperatureSensor
    };

  sensors:
  - name: "Thermostat Setpoint"
    id: thermostat_setpoint
    unit_of_measurement: °C
    accuracy_decimals: 1

  - name: "Boiler Water Temperature"
    id: boiler_water_temp
    unit_of_measurement: °C
    accuracy_decimals: 1

Logs (if applicable):

[00:38:34][VV][api.service:229]: on_connect_request: ConnectRequest {
[00:38:34]  password: '<redacted>'
[00:38:34]}
[00:38:34][D][api.connection:583]: Client 'Home Assistant 0.111.4 (172.16.1.138)' connected successfully!
[00:38:34][VV][api.service:015]: send_connect_response: ConnectResponse {
[00:38:34]  invalid_password: NO
[00:38:34]}
[00:38:34][V][app:076]: A component took a long time in a loop() cycle (1.02 s).
[00:38:34][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:34][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=18967 (now=20477)
[00:38:35][VV][api.service:264]: on_device_info_request: DeviceInfoRequest {}
[00:38:35][VV][api.service:040]: send_device_info_response: DeviceInfoResponse {
[00:38:35]  uses_password: YES
[00:38:35]  name: 'thermostat'
[00:38:35]  mac_address: '3C:71:BF:F1:E2:B8'
[00:38:35]  esphome_version: '1.14.5'
[00:38:35]  compilation_time: 'Jul 30 2020, 00:36:53'
[00:38:35]  model: 'NodeMCU-32S'
[00:38:35]  has_deep_sleep: NO
[00:38:35]}
[00:38:35][V][app:076]: A component took a long time in a loop() cycle (0.98 s).
[00:38:35][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:35][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=19967 (now=21476)
[00:38:36][VV][api.service:271]: on_list_entities_request: ListEntitiesRequest {}
[00:38:36][V][app:076]: A component took a long time in a loop() cycle (0.96 s).
[00:38:36][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:36][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=20967 (now=22451)
[00:38:37][VV][api.service:113]: send_list_entities_sensor_response: ListEntitiesSensorResponse {
[00:38:37]  object_id: 'thermostat_setpoint'
[00:38:37]  key: 3373793699
[00:38:37]  name: 'Thermostat Setpoint'
[00:38:37]  unique_id: 'thermostatsensorthermostat_setpoint'
[00:38:37]  icon: ''
[00:38:37]  unit_of_measurement: '°C'
[00:38:37]  accuracy_decimals: 1
[00:38:37]  force_update: NO
[00:38:37]}
[00:38:37][V][app:076]: A component took a long time in a loop() cycle (0.98 s).
[00:38:37][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:37][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=12917 (now=23447)
[00:38:37][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=21967 (now=23447)
[00:38:38][VV][api.service:113]: send_list_entities_sensor_response: ListEntitiesSensorResponse {
[00:38:38]  object_id: 'boiler_water_temperature'
[00:38:38]  key: 2599947121
[00:38:38]  name: 'Boiler Water Temperature'
[00:38:38]  unique_id: 'thermostatsensorboiler_water_temperature'
[00:38:38]  icon: ''
[00:38:38]  unit_of_measurement: '°C'
[00:38:38]  accuracy_decimals: 1
[00:38:38]  force_update: NO
[00:38:38]}
[00:38:38][V][app:076]: A component took a long time in a loop() cycle (0.99 s).
[00:38:38][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:38][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=22967 (now=24453)
[00:38:39][V][app:076]: A component took a long time in a loop() cycle (0.96 s).
[00:38:39][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:39][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=23967 (now=25421)
[00:38:40][V][app:076]: A component took a long time in a loop() cycle (0.95 s).
[00:38:40][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:40][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=24967 (now=26388)
[00:38:41][VV][api.service:236]: on_disconnect_request: DisconnectRequest {}
[00:38:41][VV][api.service:025]: send_disconnect_response: DisconnectResponse {}
[00:38:41][VV][api.service:203]: send_list_entities_climate_response: ListEntitiesClimateResponse {
[00:38:41]  object_id: 'thermostat'
[00:38:41]  key: 816166854
[00:38:41]  name: 'Thermostat'
[00:38:41]  unique_id: 'thermostatclimatethermostat'
[00:38:41]  supports_current_temperature: YES
[00:38:41]  supports_two_point_target_temperature: NO
[00:38:41]  supported_modes: CLIMATE_MODE_AUTO
[00:38:41]  supported_modes: CLIMATE_MODE_OFF
[00:38:41]  supported_modes: CLIMATE_MODE_HEAT
[00:38:41]  visual_min_temperature: 18
[00:38:41]  visual_max_temperature: 28
[00:38:41]  visual_temperature_step: 1
[00:38:41]  supports_away: NO
[00:38:41]  supports
[00:38:41][V][app:076]: A component took a long time in a loop() cycle (1.00 s).
[00:38:41][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:41][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=25967 (now=27413)
[00:38:42][D][api:067]: Disconnecting Home Assistant 0.111.4 (172.16.1.138)
[00:38:42][VV][api.service:222]: on_hello_request: HelloRequest {
[00:38:42]  client_info: 'Home Assistant 0.111.4'
[00:38:42]}
[00:38:42][V][api.connection:567]: Hello from client: 'Home Assistant 0.111.4 (172.16.1.138)'
[00:38:42][VV][api.service:010]: send_hello_response: HelloResponse {
[00:38:42]  api_version_major: 1
[00:38:42]  api_version_minor: 3
[00:38:42]  server_info: 'thermostat (esphome v1.14.5)'
[00:38:42]}
[00:38:42][V][app:076]: A component took a long time in a loop() cycle (0.99 s).
[00:38:42][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:42][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=26967 (now=28420)
[00:38:43][VV][api.service:229]: on_connect_request: ConnectRequest {
[00:38:43]  password: '<redacted>'
[00:38:43]}
[00:38:43][D][api.connection:583]: Client 'Home Assistant 0.111.4 (172.16.1.138)' connected successfully!
[00:38:43][VV][api.service:015]: send_connect_response: ConnectResponse {
[00:38:43]  invalid_password: NO
[00:38:43]}
[00:38:43][V][app:076]: A component took a long time in a loop() cycle (0.98 s).
[00:38:43][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:43][VV][scheduler:131]: Running interval 'update' with interval=10000 last_execution=18589 (now=29414)
[00:38:43][V][sensor:013]: 'Thermostat Setpoint': Received new state 23.000000
[00:38:43][D][sensor:092]: 'Thermostat Setpoint': Sending state 23.00000 °C with 1 decimals of accuracy
[00:38:43][V][sensor:013]: 'Boiler Water Temperature': Received new state 0.000000
[00:38:43][D][sensor:092]: 'Boiler Water Temperature': Sending state 0.00000 °C with 1 decimals of accuracy
[00:38:43][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=27967 (now=29414)
[00:38:44][VV][api.service:264]: on_device_info_request: DeviceInfoRequest {}
[00:38:44][VV][api.service:040]: send_device_info_response: DeviceInfoResponse {
[00:38:44]  uses_password: YES
[00:38:44]  name: 'thermostat'
[00:38:44]  mac_address: '3C:71:BF:F1:E2:B8'
[00:38:44]  esphome_version: '1.14.5'
[00:38:44]  compilation_time: 'Jul 30 2020, 00:36:53'
[00:38:44]  model: 'NodeMCU-32S'
[00:38:44]  has_deep_sleep: NO
[00:38:44]}
[00:38:44][V][app:076]: A component took a long time in a loop() cycle (1.02 s).
[00:38:44][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:44][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=28967 (now=30456)
[00:38:45][VV][api.service:271]: on_list_entities_request: ListEntitiesRequest {}
[00:38:45][V][app:076]: A component took a long time in a loop() cycle (0.96 s).
[00:38:45][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:45][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=29967 (now=31431)
[00:38:46][VV][api.service:113]: send_list_entities_sensor_response: ListEntitiesSensorResponse {
[00:38:46]  object_id: 'thermostat_setpoint'
[00:38:46]  key: 3373793699
[00:38:46]  name: 'Thermostat Setpoint'
[00:38:46]  unique_id: 'thermostatsensorthermostat_setpoint'
[00:38:46]  icon: ''
[00:38:46]  unit_of_measurement: '°C'
[00:38:46]  accuracy_decimals: 1
[00:38:46]  force_update: NO
[00:38:46]}
[00:38:46][V][app:076]: A component took a long time in a loop() cycle (0.98 s).
[00:38:46][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:46][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=30967 (now=32427)
[00:38:47][VV][api.service:113]: send_list_entities_sensor_response: ListEntitiesSensorResponse {
[00:38:47]  object_id: 'boiler_water_temperature'
[00:38:47]  key: 2599947121
[00:38:47]  name: 'Boiler Water Temperature'
[00:38:47]  unique_id: 'thermostatsensorboiler_water_temperature'
[00:38:47]  icon: ''
[00:38:47]  unit_of_measurement: '°C'
[00:38:47]  accuracy_decimals: 1
[00:38:47]  force_update: NO
[00:38:47]}
[00:38:47][V][app:076]: A component took a long time in a loop() cycle (0.98 s).
[00:38:47][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:47][VV][scheduler:131]: Running interval '' with interval=10000 last_execution=22917 (now=33424)
[00:38:47][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=31967 (now=33424)
[00:38:48][V][app:076]: A component took a long time in a loop() cycle (0.96 s).
[00:38:48][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:48][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=32967 (now=34401)
[00:38:49][V][app:076]: A component took a long time in a loop() cycle (0.95 s).
[00:38:49][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:49][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=33967 (now=35368)
[00:38:50][VV][api.service:236]: on_disconnect_request: DisconnectRequest {}
[00:38:50][VV][api.service:025]: send_disconnect_response: DisconnectResponse {}
[00:38:50][VV][api.service:203]: send_list_entities_climate_response: ListEntitiesClimateResponse {
[00:38:50]  object_id: 'thermostat'
[00:38:50]  key: 816166854
[00:38:50]  name: 'Thermostat'
[00:38:50]  unique_id: 'thermostatclimatethermostat'
[00:38:50]  supports_current_temperature: YES
[00:38:50]  supports_two_point_target_temperature: NO
[00:38:50]  supported_modes: CLIMATE_MODE_AUTO
[00:38:50]  supported_modes: CLIMATE_MODE_OFF
[00:38:50]  supported_modes: CLIMATE_MODE_HEAT
[00:38:50]  visual_min_temperature: 18
[00:38:50]  visual_max_temperature: 28
[00:38:50]  visual_temperature_step: 1
[00:38:50]  supports_away: NO
[00:38:50]  supports
[00:38:50][V][app:076]: A component took a long time in a loop() cycle (1.00 s).
[00:38:50][V][app:077]: Components should block for at most 20-30ms in loop().
[00:38:50][VV][scheduler:131]: Running interval 'update' with interval=1000 last_execution=34967 (now=36393)
[00:38:51][D][api:067]: Disconnecting Home Assistant 0.111.4 (172.16.1.138)

At the same time, Home Assistant log with aioesphomeapi.connection turned to debug looks like this:

Jul 29 22:38:34 hass hass[16578]: 2020-07-29 22:38:34 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to thermostat.local
Jul 29 22:38:34 hass hass[16578]: 2020-07-29 22:38:34 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.DeviceInfoRequest'>: 
Jul 29 22:38:35 hass hass[16578]: 2020-07-29 22:38:35 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.DeviceInfoResponse'>: uses_password: true
Jul 29 22:38:35 hass hass[16578]: name: "thermostat"
Jul 29 22:38:35 hass hass[16578]: mac_address: "3C:71:BF:F1:E2:B8"
Jul 29 22:38:35 hass hass[16578]: esphome_version: "1.14.5"
Jul 29 22:38:35 hass hass[16578]: compilation_time: "Jul 30 2020, 00:36:53"
Jul 29 22:38:35 hass hass[16578]: model: "NodeMCU-32S"
Jul 29 22:38:35 hass hass[16578]: 
Jul 29 22:38:35 hass hass[16578]: 2020-07-29 22:38:35 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.ListEntitiesRequest'>: 
Jul 29 22:38:37 hass hass[16578]: 2020-07-29 22:38:37 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.ListEntitiesSensorResponse'>: object_id: "thermostat_setpoint"
Jul 29 22:38:37 hass hass[16578]: key: 3373793699
Jul 29 22:38:37 hass hass[16578]: name: "Thermostat Setpoint"
Jul 29 22:38:37 hass hass[16578]: unique_id: "thermostatsensorthermostat_setpoint"
Jul 29 22:38:37 hass hass[16578]: unit_of_measurement: "\302\260C"
Jul 29 22:38:37 hass hass[16578]: accuracy_decimals: 1
Jul 29 22:38:37 hass hass[16578]: 
Jul 29 22:38:38 hass hass[16578]: 2020-07-29 22:38:38 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.ListEntitiesSensorResponse'>: object_id: "boiler_water_temperature"
Jul 29 22:38:38 hass hass[16578]: key: 2599947121
Jul 29 22:38:38 hass hass[16578]: name: "Boiler Water Temperature"
Jul 29 22:38:38 hass hass[16578]: unique_id: "thermostatsensorboiler_water_temperature"
Jul 29 22:38:38 hass hass[16578]: unit_of_measurement: "\302\260C"
Jul 29 22:38:38 hass hass[16578]: accuracy_decimals: 1
Jul 29 22:38:38 hass hass[16578]: 
Jul 29 22:38:40 hass hass[16578]: 2020-07-29 22:38:40 WARNING (MainThread) [homeassistant.components.esphome] Error getting initial data: Timeout while waiting for API response!
Jul 29 22:38:40 hass hass[16578]: 2020-07-29 22:38:40 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.DisconnectRequest'>: 
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.DisconnectResponse'>: 
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Closed socket
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for thermostat.local
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 INFO (MainThread) [aioesphomeapi.connection] thermostat.local: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Connecting to thermostat.local:6053 (('172.16.1.119', 6053))
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Opened socket for
Jul 29 22:38:41 hass hass[16578]: 2020-07-29 22:38:41 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.HelloRequest'>: client_info: "Home Assistant 0.111.4"
Jul 29 22:38:41 hass hass[16578]: 
Jul 29 22:38:42 hass hass[16578]: 2020-07-29 22:38:42 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.HelloResponse'>: api_version_major: 1
Jul 29 22:38:42 hass hass[16578]: api_version_minor: 3
Jul 29 22:38:42 hass hass[16578]: server_info: "thermostat (esphome v1.14.5)"
Jul 29 22:38:42 hass hass[16578]: 
Jul 29 22:38:42 hass hass[16578]: 2020-07-29 22:38:42 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Successfully connected ('thermostat (esphome v1.14.5)' API=1.3)
Jul 29 22:38:42 hass hass[16578]: 2020-07-29 22:38:42 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.ConnectRequest'>: password: "<redacted>"
Jul 29 22:38:42 hass hass[16578]: 
Jul 29 22:38:43 hass hass[16578]: 2020-07-29 22:38:43 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.ConnectResponse'>: 
Jul 29 22:38:43 hass hass[16578]: 2020-07-29 22:38:43 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to thermostat.local
Jul 29 22:38:43 hass hass[16578]: 2020-07-29 22:38:43 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.DeviceInfoRequest'>: 
Jul 29 22:38:44 hass hass[16578]: 2020-07-29 22:38:44 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.DeviceInfoResponse'>: uses_password: true
Jul 29 22:38:44 hass hass[16578]: name: "thermostat"
Jul 29 22:38:44 hass hass[16578]: mac_address: "3C:71:BF:F1:E2:B8"
Jul 29 22:38:44 hass hass[16578]: esphome_version: "1.14.5"
Jul 29 22:38:44 hass hass[16578]: compilation_time: "Jul 30 2020, 00:36:53"
Jul 29 22:38:44 hass hass[16578]: model: "NodeMCU-32S"
Jul 29 22:38:44 hass hass[16578]: 
Jul 29 22:38:44 hass hass[16578]: 2020-07-29 22:38:44 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.ListEntitiesRequest'>: 
Jul 29 22:38:46 hass hass[16578]: 2020-07-29 22:38:46 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.ListEntitiesSensorResponse'>: object_id: "thermostat_setpoint"
Jul 29 22:38:46 hass hass[16578]: key: 3373793699
Jul 29 22:38:46 hass hass[16578]: name: "Thermostat Setpoint"
Jul 29 22:38:46 hass hass[16578]: unique_id: "thermostatsensorthermostat_setpoint"
Jul 29 22:38:46 hass hass[16578]: unit_of_measurement: "\302\260C"
Jul 29 22:38:46 hass hass[16578]: accuracy_decimals: 1
Jul 29 22:38:46 hass hass[16578]: 
Jul 29 22:38:47 hass hass[16578]: 2020-07-29 22:38:47 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.ListEntitiesSensorResponse'>: object_id: "boiler_water_temperature"
Jul 29 22:38:47 hass hass[16578]: key: 2599947121
Jul 29 22:38:47 hass hass[16578]: name: "Boiler Water Temperature"
Jul 29 22:38:47 hass hass[16578]: unique_id: "thermostatsensorboiler_water_temperature"
Jul 29 22:38:47 hass hass[16578]: unit_of_measurement: "\302\260C"
Jul 29 22:38:47 hass hass[16578]: accuracy_decimals: 1
Jul 29 22:38:47 hass hass[16578]: 
Jul 29 22:38:49 hass hass[16578]: 2020-07-29 22:38:49 WARNING (MainThread) [homeassistant.components.esphome] Error getting initial data: Timeout while waiting for API response!
Jul 29 22:38:49 hass hass[16578]: 2020-07-29 22:38:49 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.DisconnectRequest'>: 
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.DisconnectResponse'>: 
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Closed socket
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 INFO (MainThread) [homeassistant.components.esphome] Disconnected from ESPHome API for thermostat.local
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 INFO (MainThread) [aioesphomeapi.connection] thermostat.local: Error while reading incoming messages: Error while receiving data: 0 bytes read on a total of 1 expected bytes
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Connecting to thermostat.local:6053 (('172.16.1.119', 6053))
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Opened socket for
Jul 29 22:38:50 hass hass[16578]: 2020-07-29 22:38:50 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.HelloRequest'>: client_info: "Home Assistant 0.111.4"
Jul 29 22:38:50 hass hass[16578]: 
Jul 29 22:38:51 hass hass[16578]: 2020-07-29 22:38:51 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Got message of type <class 'api_pb2.HelloResponse'>: api_version_major: 1
Jul 29 22:38:51 hass hass[16578]: api_version_minor: 3
Jul 29 22:38:51 hass hass[16578]: server_info: "thermostat (esphome v1.14.5)"
Jul 29 22:38:51 hass hass[16578]: 
Jul 29 22:38:51 hass hass[16578]: 2020-07-29 22:38:51 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Successfully connected ('thermostat (esphome v1.14.5)' API=1.3)
Jul 29 22:38:51 hass hass[16578]: 2020-07-29 22:38:51 DEBUG (MainThread) [aioesphomeapi.connection] thermostat.local: Sending <class 'api_pb2.ConnectRequest'>: password: "<redacted>"
Jul 29 22:38:51 hass hass[16578]:

Additional information and things you've tried: The minimal custom component to reproduce this issue looks like this (I deliberately removed all real functionality because a simple delay() is enough to reproduce)

#include "esphome.h"
#include "OpenTherm.h"

const int inPin = 4; // 2 for Arduino, 4 for ESP8266
const int outPin = 5; //3 for Arduino, 5 for ESP8266

float sp = 23, //set point
pv = 0, //current temperature
pv_last = 0, //prior temperature
ierr = 0, //integral error
dt = 0, //time between measurements
op = 0; //PID controller output
unsigned long ts = 0, new_ts = 0; //timestamp

// stuff for sensors
float wt = 0; // internal water temp

OpenTherm ot(inPin, outPin);

void ICACHE_RAM_ATTR handleInterrupt() {
  ot.handleInterrupt();
}

class Thermostat : public PollingComponent {
  public:
  Thermostat() : PollingComponent(1000) {}

  void setup() override {
    // This will be called by App.setup()
    ESP_LOGI("thermostat", "Starting OpenTherm component");
  }

  void update() override {
    delay(954);
  }

};

class ThermostatSensor : public PollingComponent, public Sensor {
 public:
  ThermostatSensor() : PollingComponent(10000) {}

  Sensor *setpointSensor = new Sensor();
  Sensor *hotWaterTemperatureSensor = new Sensor();

  void setup() override {
    // This will be called by App.setup()
  }

  void update() override {
    setpointSensor->publish_state(sp);
    hotWaterTemperatureSensor->publish_state(wt);
  }
};
probot-esphome[bot] commented 4 years ago

api source api issues api recent changes (message by IssueLinks)

OttoWinter commented 4 years ago

Hmm, yeah we could handle that a bit better (but certainly running once every second will not be officially supported, as many other things like binary sensors etc also suffer). Probably just a timeout value that needs to be updated somewhere in aioesphomeapi

unbreakab1e commented 4 years ago

Yeah, of course I was thinking that I am trying to do something really strange and unsupported here 😅 Running OpenTherm communication in a loop() instead of update() produces the same result, so maybe there are some better options to implement such a custom component I should investigate? Maybe some async communication with boiler is possible? Unfortunately I couldn't find any examples in the ESPHome docs or DIY section and I only recently started using C++ so I cannot devise a solution myself yet. If this is not possible, well, then the ability to increase aioesphomeapi timeout in hass configuration will do the trick.

glmnet commented 4 years ago

Otto is saying that aioesphome shouldn't die if ESPHome dosn't replay quickly which is ok,

however it seems you don't know how to deal with this? In general when you delay() for more than 16ms = 1000ms / 60hz (ESPHome loop rate) then you might be halting the processor unnecessarily. You'll do lower delays only when handling very little delays.

Your polling component is to be called every 10 seconds, so you don't need to delay any, just let the function end and it will be called again in 10 seconds, and aioesphome will be happy.

unbreakab1e commented 4 years ago

The thing is that as far as I understand the OpenTherm specification, master device (thermostat) should communicate with slave device (boiler) at least every second. At the same time it allows a response time ranging from 20 to 800 milliseconds. Arduino implementations are leaning towards longer periods and they have a hardcoded timeout of one second after which they present communication failure.

I will have immediate access to boiler only the next weekend, so right now I am preparing the software and package for the thermostat beforehand, and there are two possibilities. In case my boiler is fast to respond, running a loop() inside Generic Component with small delays and having a separate Polling Component to present sensor values should be ok, right? But if it is slow to communicate, and the OpenTherm library will block for 800ms, are there any ways to deal with it in ESPHome?

Bart-1992 commented 3 years ago

Hi @unbreakab1e ,

I found this issue after posting mine : https://github.com/esphome/issues/issues/1455. I'm currently experiencing the exact same issues.

Did you managed to fix this within ESPhome? Or are you using the MQTT solution ?

It looks like this is going to be impossible to solve within ESPhome unfortunately.

stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.