RISCO integration error after upgrade core to 2024.2.4 or 2024.2.5

Claudio1L commented 4 months ago

The problem

after upgrade core to 2024.2.4 or 2024.2.5 started receiving following errors, with some alarm sensor going in state "unknown". Usually a reload of the integration fix it.

Those are started after a restart of the Core

Home Assistant Core 2024-03-12 13:21:35.089 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 16 2024-03-12 13:21:35.090 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-12 13:21:35.091 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-12 13:21:35.091 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-12 13:21:35.091 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-12 13:21:35.091 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-12 13:21:35.091 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-12 13:27:22.393 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 26 2024-03-12 13:27:27.337 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 26 2024-03-12 13:27:31.197 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:27:39.256 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:30:29.172 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:30:32.188 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:30:34.382 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:30:37.248 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:30:39.242 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:30:41.307 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:00.230 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:07.205 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:16.300 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:19.168 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:33.287 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:36.197 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:53.241 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:55.286 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:56.333 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:31:58.350 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:12.214 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:17.541 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:25.243 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:27.208 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:35.211 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:37.377 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:46.230 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:32:49.196 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:00.250 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:07.376 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:08.292 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:11.185 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:20.193 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:22.203 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:31.272 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:33:34.238 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:34:08.214 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25 2024-03-12 13:34:11.180 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 25

What version of Home Assistant Core has the issue?

System Information version | core-2024.2.5 -- | -- installation_type | Home Assistant Core dev | false hassio | false docker | false user | root virtualenv | true python_version | 3.12.2 os_name | Linux os_version | 6.5.13-1-pve arch | x86_64 timezone | Europe/Rome config_dir | /root/.homeassistant
Home Assistant Community Store
GitHub API | ok -- | -- GitHub Content | ok GitHub Web | ok GitHub API Calls Remaining | 4610 Installed Version | 1.34.0 Stage | running Available Repositories | 1481 Downloaded Repositories | 71

AccuWeather
can_reach_server | ok -- | -- remaining_requests | 27

Home Assistant Cloud
logged_in | true -- | -- subscription_expiration | November 1, 2024 at 01:00 relayer_connected | true relayer_region | eu-central-1 remote_enabled | true remote_connected | true alexa_enabled | true google_enabled | false remote_server | eu-central-1-2.ui.nabu.casa certificate_status | ready instance_id | 937634e48fxxxxxxxxxxxfc15fc4xxxxxxfe can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok

Dashboards
dashboards | 18 -- | -- resources | 36 views | 67 mode | storage

Recorder
oldest_recorder_run | March 9, 2024 at 04:55 -- | -- current_recorder_run | March 12, 2024 at 13:20 estimated_db_size | 1067.30 MiB database_engine | mysql database_version | 11.3.2

Sonoff
version | 3.6.0 (8dd8af9) -- | -- cloud_online | 16 / 16 local_online | 15 / 15

Spotify
api_endpoint_reachable | ok -- | --

What was the last working version of Home Assistant Core?

Probably 2024.2.3 or 2024.2.2

What type of installation are you running?

Core

Integration causing the issue

RISCO

Link to integration documentation on our website

https://github.com/home-assistant/core/tree/dev/homeassistant/components/risco

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 4 months ago

Hey there @onfreund, mind taking a look at this issue as it has been labeled with an integration (risco) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `risco` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign risco` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

risco documentation risco source _{^{(message by IssueLinks)}}

OnFreund commented 4 months ago

Have you tried 2024.3?

Claudio1L commented 4 months ago

updated just now.

As soon as rebooted:

Home Assistant Core 2024-03-13 07:39:49.585 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: 2 2024-03-13 07:39:49.585 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-13 07:39:49.586 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-13 07:39:49.586 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-13 07:39:49.587 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-03-13 07:39:49.587 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: Timeout in command: CLOCK

same if not worst

going back because of additional errors from other part that I do not want to debug now

OnFreund commented 4 months ago

I have a suspicion that recent versions of HA load so fast that Risco isn't ready to accept a new connection. Try disabling the integration, restarting HA, waiting 5 seconds after HA is up, and then enable the integration again.

Claudio1L commented 4 months ago

Confirmed. Tried 3 times, no errors

OnFreund commented 4 months ago

OK, one more thing for you to check - does your config entry have a communication_delay that's higher than 0?

Claudio1L commented 4 months ago

if you mean the HA configuration.yaml, no delay setting at all. Let me know if I should

OnFreund commented 4 months ago

You should look in .storage/core.config_entries

Claudio1L commented 4 months ago

now is "communication_delay": 3

OnFreund commented 4 months ago

I have a suspicion that https://github.com/home-assistant/core/pull/101349 caused more harm than good (FYI @FredericMa). I've seen some problems with my environment, and changing this back to 0 seems to have solved them. What I think is happening:

HA is booting so quickly that Risco is not yet ready for another connection
After a couple of failed attempts, it succeeds, and HA updates the communication delay to 3 seconds, thinking that was the reason for the failed attempts.
The 3 second delay is causing problems of its own (we already know that Risco connections are flaky if a keep alive isn't sent every few seconds, for example.

We may have to revert that change. In the meantime, try to change it back to 0. The simplest way, if you haven't made any major modification to the integration options or device/entity names, is to to remove the existing instance and add it again.

Claudio1L commented 4 months ago

after reinstalling, first boot went fine, the second:

OnFreund commented 4 months ago

Just to confirm:

You removed and re-added the application and everything worked
You restarted HA - everything worked
You restarted again - errors

Right?

FredericMa commented 4 months ago

About https://github.com/home-assistant/core/pull/101349, I was indeed expecting this behavior. If one time something goes wrong or is a bit delayed at startup you get to the wait time of 3 seconds... That's why I was more in favor of just having a configuration parameter in place so people can configure it themselves to the value that fits their environment.

I've no issues with reverting it but then how can we solve this issue that https://github.com/home-assistant/core/pull/101349 was supposed to solve?

OnFreund commented 4 months ago

Actually back when we merged #101349 this was way less likely. I believe the recent boot optimizations made this more likely. I'll expand in my PR for the fix. I'm going to revert just the init part and keep the config flow part intact. I would also wonder if a delay between connection and first command is the right approach. Did you try a delay before the connection? We know that Risco panels can take a while between closing a connection and being able to accept a new one.

FredericMa commented 4 months ago

Yes, I experimented with it to pinpoint the actual issue I was facing. A delay before connecting didn't make any difference.

Claudio1L commented 3 months ago

Hi @OnFreund part of the issue is still there in 2024.4.2. At the HA reboot 2024-04-10 07:21:49.473 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.473 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.474 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.474 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.474 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.474 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.474 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state 2024-04-10 07:21:49.474 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library: invalid state

OnFreund commented 3 months ago

2024.4.3 will allow you to control the concurrency. Try lower values and see if it helps.

Claudio1L commented 3 months ago

if possible, is going worst. Concurrent requests = 1

2024-04-14 09:14:35.282 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 77, in _listen 2024-04-14 09:14:35.293 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 77, in _listen 2024-04-14 09:18:58.460 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 109, in send_command File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 87, in _keep_alive File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 98, in send_result_command File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 111, in send_command pyrisco.common.OperationError: Timeout in command: CLOCK 2024-04-14 09:18:58.617 ERROR (MainThread) [homeassistant.components.risco] Error in Risco library File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 77, in _listen

Logger: homeassistant.components.risco Source: /srv/homeassistant/lib/python3.12/site-packages/homeassistant/components/risco/init.py:104 integration: Risco (documentation, issues) First occurred: 09:18:58 (1 occurrences) Last logged: 09:18:58 Error in Risco library

Traceback (most recent call last): File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 77, in _listen future.set_result(command) asyncio.exceptions.InvalidStateError: invalid state

Logger: homeassistant.components.risco Source: /srv/homeassistant/lib/python3.12/site-packages/homeassistant/components/risco/init.py:104 integration: Risco (documentation, issues) First occurred: 09:18:58 (1 occurrences) Last logged: 09:18:58 Error in Risco library

Traceback (most recent call last): File "/usr/local/lib/python3.12/asyncio/tasks.py", line 520, in wait_for return await fut ^^^^^^^^^ asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 109, in send_command return await asyncio.wait_for(future, 1) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/asyncio/tasks.py", line 519, in wait_for async with timeouts.timeout(timeout): File "/usr/local/lib/python3.12/asyncio/timeouts.py", line 115, in aexit raise TimeoutError from exc_val TimeoutError

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 87, in _keep_alive await self.send_result_command("CLOCK") File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 98, in send_result_command command = await self.send_command(command) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/srv/homeassistant/lib/python3.12/site-packages/pyrisco/local/risco_socket.py", line 111, in send_command raise OperationError(f'Timeout in command: {command}') pyrisco.common.OperationError: Timeout in command: CLOCK

home-assistant / core