scottyphillips / echonetlite_homeassistant

A Home Assistant custom component for use with ECHONET enabled devices.
MIT License
129 stars 42 forks source link

Latest update not starting properly #122

Closed girkers closed 1 year ago

girkers commented 1 year ago

When starting HA after updating to the latest version is causing issues on start up, my log is showing:

Updating echonetlite select took longer than the scheduled update interval 0:00:30 8:14:30 PM – (WARNING) Select - message first occurred at 8:12:30 PM and shows up 5 times Updating echonetlite climate took longer than the scheduled update interval 0:01:00 8:14:30 PM – (WARNING) Climate - message first occurred at 8:13:30 PM and shows up 2 times Waiting on integrations to complete setup: echonetlite 8:14:18 PM – (WARNING) bootstrap.py - message first occurred at 8:09:17 PM and shows up 6 times Setup timed out for stage 2 - moving forward 8:14:17 PM – (WARNING) bootstrap.py Setup of sensor platform echonetlite is taking over 10 seconds. 8:11:40 PM – (WARNING) Sensor

aftertommy commented 1 year ago

I believe I’m seeing the same issue.

nao-pon commented 1 year ago

I don't know if it solves this problem, but we have released a new version of pychonet, 2.3.12.

Could you try this pychonet 2.3.12 ?

Try changing the below line in custom_components/echonetlite/manifest.json and restart HA.

From

  "requirements": [
    "pychonet==2.3.10"
  ],

To

  "requirements": [
    "pychonet==2.3.12"
  ],
tredger commented 1 year ago

I have this issue too, updating the manifest to use pychonet 2.3.12 doesn't resolve the issue. I'm running version 2022.11.5 of Home Assistant. The following is my log, and the took longer than the scheduled update interval log entries repeat. Any other ideas?

| 2023-01-08 08:09:53.678 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: echonetlite
| 2023-01-08 08:10:10.118 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.echonetlite
| 2023-01-08 08:10:10.121 INFO (MainThread) [homeassistant.components.climate] Setting up climate.echonetlite
| 2023-01-08 08:10:10.123 INFO (MainThread) [homeassistant.components.select] Setting up select.echonetlite
| 2023-01-08 08:10:10.125 INFO (MainThread) [homeassistant.components.light] Setting up light.echonetlite
| 2023-01-08 08:10:10.126 INFO (MainThread) [homeassistant.components.fan] Setting up fan.echonetlite
| 2023-01-08 08:10:10.127 INFO (MainThread) [homeassistant.components.switch] Setting up switch.echonetlite
| 2023-01-08 08:10:10.127 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.echonetlite
| 2023-01-08 08:10:10.128 INFO (MainThread) [homeassistant.components.climate] Setting up climate.echonetlite
| 2023-01-08 08:10:10.128 INFO (MainThread) [homeassistant.components.select] Setting up select.echonetlite
| 2023-01-08 08:10:10.128 INFO (MainThread) [homeassistant.components.light] Setting up light.echonetlite
| 2023-01-08 08:10:10.128 INFO (MainThread) [homeassistant.components.fan] Setting up fan.echonetlite
| 2023-01-08 08:10:10.128 INFO (MainThread) [homeassistant.components.switch] Setting up switch.echonetlite
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.sensor] kitchen-heatump Measured cumulative power consumption(133): _should_poll is True
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.sensor] kitchen-heatump Measured outdoor air temperature(190): _should_poll is True
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.sensor] kitchen-heatump Measured value of room temperature(187): _should_poll is True
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.select] kitchen-heatump(160): _should_poll is False
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.select] kitchen-heatump(161): _should_poll is True
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.select] kitchen-heatump(163): _should_poll is True
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.select] kitchen-heatump(164): _should_poll is True
| 2023-01-08 08:10:10.129 INFO (MainThread) [custom_components.echonetlite.select] kitchen-heatump(165): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.sensor] lounge-heatpump Measured cumulative power consumption(133): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.sensor] lounge-heatpump Measured outdoor air temperature(190): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.sensor] lounge-heatpump Measured value of room temperature(187): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.select] lounge-heatpump(160): _should_poll is False
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.select] lounge-heatpump(161): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.select] lounge-heatpump(163): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.select] lounge-heatpump(164): _should_poll is True
| 2023-01-08 08:10:10.130 INFO (MainThread) [custom_components.echonetlite.select] lounge-heatpump(165): _should_poll is True
| 2023-01-08 08:10:20.119 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform echonetlite is taking over 10 seconds.
| 2023-01-08 08:10:20.129 WARNING (MainThread) [homeassistant.components.sensor] Setup of sensor platform echonetlite is taking over 10 seconds.
| 2023-01-08 08:10:50.140 WARNING (MainThread) [homeassistant.helpers.entity] Update of select.kitchen_heatump_air_flow_rate_setting is taking over 10 seconds
| 2023-01-08 08:10:50.141 WARNING (MainThread) [homeassistant.helpers.entity] Update of select.lounge_heatpump_air_flow_rate_setting is taking over 10 seconds
| 2023-01-08 08:10:53.740 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: echonetlite, sensor.echonetlite, sensor.echonetlite_2
| 2023-01-08 08:11:10.139 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:11:10.140 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:11:20.139 WARNING (MainThread) [homeassistant.helpers.entity] Update of climate.kitchen_heatump is taking over 10 seconds
| 2023-01-08 08:11:20.140 WARNING (MainThread) [homeassistant.helpers.entity] Update of climate.lounge_heatpump is taking over 10 seconds
| 2023-01-08 08:11:40.139 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:11:40.141 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:11:53.799 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: echonetlite, sensor.echonetlite, sensor.echonetlite_2
| 2023-01-08 08:12:10.139 WARNING (MainThread) [homeassistant.components.climate] Updating echonetlite climate took longer than the scheduled update interval 0:01:00
| 2023-01-08 08:12:10.141 WARNING (MainThread) [homeassistant.components.climate] Updating echonetlite climate took longer than the scheduled update interval 0:01:00
| 2023-01-08 08:12:10.142 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:12:10.143 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:12:40.143 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:12:40.144 WARNING (MainThread) [homeassistant.components.select] Updating echonetlite select took longer than the scheduled update interval 0:00:30
| 2023-01-08 08:12:51.017 WARNING (MainThread) [homeassistant.bootstrap] Setup timed out for stage 2 - moving forward
nao-pon commented 1 year ago

What was the last version of echonetlite integration that worked?

nao-pon commented 1 year ago

Also, please download the master version with HACS, modify configuration.yaml to output debug logs as shown below, restart HA, and let us know the logs extracted by "echonetlite".

logger:
  logs:
    custom_components.echonetlite: debug
tredger commented 1 year ago

Hi. After some debugging turns out the network interface HA was assigned to lost the VLAN that put it on the same network as the heatpump units, so it wasn't getting the broadcast traffic. After starting I could initiate actions from home assistant on the units, but not see the status of the unit. I'm fairly confident this wasn't the case with the 568 i had previously, but it definitely is with the two 578s I have now. Either way, thats a separate issue and was causing the start up issues for me. I couldn't tell you if it's related to the two others who were having issues.

aftertommy commented 1 year ago

@nao-pon I'm sorry for not replying to your request for logs sooner. My issue might be different from the original reported here, and if so I'd be happy to create a new one.

Basically, the echonet lite integration seems to be taking longer to load since recently updating the integration and HASS to current releases. I haven't added any new echonet devices to my home. I see a lot messages like these in the logs:

2023-02-05 00:47:31.182 WARNING (MainThread) [homeassistant.components.sensor] Updating echonetlite sensor took longer than the scheduled update interval 0:00:30
2023-02-05 00:46:09.316 WARNING (MainThread) [homeassistant.helpers.entity] Update of select.living_ac_air_flow_rate_setting is taking over 10 seconds

For the "taking over 10 seconds" logs, it's not always the same device, but it appears to always be either the air_flow_rate_setting or measured_cumulative_power_consumption entities of each device.

There are also logs of this form, which I appreciate may just be temporary, but just in case:

Sensor sensor.living_ac_measured_value_of_room_temperature has device class temperature, state class measurement and unit °C thus indicating it has a numeric value; however, it has the non-numeric value: unavailable (<class 'str'>); Please update your configuration if your entity is manually configured, otherwise report it to the custom integration author.

I've attached my logs to this reply. echonet_logs.txt

nao-pon commented 1 year ago

@aftertommy In my case, it is reported that the load time of each integration is slowed down with the HA update, but somehow it seems that each integration is being processed in parallel, so depending on the number of integrations installed, Proportionally longer times seem to be reported. However, I feel that the total time does not change so much. The echonetlite integration also seems to take a long time to load, but it never fails to start for me.

Does your echonetlite integration sometimes fail to start? I've had a quick look at the logs and it doesn't seem to be a problem.

aftertommy commented 1 year ago

I don’t think it’s failed to start.

nao-pon commented 1 year ago

For reference, I checked with HA core-2023.3.6 and the ECHONT Lite integration startup time seems to be significantly reduced.