Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rainbird integration still unstable #92857

Closed
konikvranik opened this issue May 9, 2023 · 85 comments · Fixed by #95968
Closed

Rainbird integration still unstable #92857

konikvranik opened this issue May 9, 2023 · 85 comments · Fixed by #95968

Comments

@konikvranik
Copy link
Contributor

konikvranik commented May 9, 2023

The problem

The Rainbird integration still oscilating between available/unavailable states:

May 09 12:48:54 hass.home hass[32258]: 2023-05-09 12:48:54.376 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 12:48:54 hass.home hass[32258]: 2023-05-09 12:48:54.402 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.178 seconds (success: False)

image

What version of Home Assistant Core has the issue?

2023.5.2

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

Rainbird

Link to integration documentation on our website

https://www.home-assistant.io/integrations/rainbird

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

ay 09 15:11:51 hass.home hass[32258]: 2023-05-09 15:11:51.202 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:11:51 hass.home hass[32258]: 2023-05-09 15:11:51.203 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.150 seconds (success: True)
May 09 15:12:51 hass.home hass[32258]: 2023-05-09 15:12:51.204 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:12:51 hass.home hass[32258]: 2023-05-09 15:12:51.253 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.201 seconds (success: False)
May 09 15:13:52 hass.home hass[32258]: 2023-05-09 15:13:52.120 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:13:52 hass.home hass[32258]: 2023-05-09 15:13:52.121 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.069 seconds (success: True)
May 09 15:14:52 hass.home hass[32258]: 2023-05-09 15:14:52.199 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:14:52 hass.home hass[32258]: 2023-05-09 15:14:52.244 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.192 seconds (success: False)
May 09 15:15:53 hass.home hass[32258]: 2023-05-09 15:15:53.537 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:15:53 hass.home hass[32258]: 2023-05-09 15:15:53.538 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.486 seconds (success: True)
May 09 15:16:53 hass.home hass[32258]: 2023-05-09 15:16:53.231 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:16:53 hass.home hass[32258]: 2023-05-09 15:16:53.314 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.262 seconds (success: False)
May 09 15:17:54 hass.home hass[32258]: 2023-05-09 15:17:54.305 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:17:54 hass.home hass[32258]: 2023-05-09 15:17:54.306 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.254 seconds (success: True)
May 09 15:18:54 hass.home hass[32258]: 2023-05-09 15:18:54.203 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:18:54 hass.home hass[32258]: 2023-05-09 15:18:54.251 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.199 seconds (success: False)
May 09 15:19:55 hass.home hass[32258]: 2023-05-09 15:19:55.221 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:19:55 hass.home hass[32258]: 2023-05-09 15:19:55.221 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.168 seconds (success: True)
May 09 15:20:55 hass.home hass[32258]: 2023-05-09 15:20:55.229 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:20:55 hass.home hass[32258]: 2023-05-09 15:20:55.275 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.206 seconds (success: False)
May 09 15:21:56 hass.home hass[32258]: 2023-05-09 15:21:56.140 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:21:56 hass.home hass[32258]: 2023-05-09 15:21:56.141 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.090 seconds (success: True)
May 09 15:22:56 hass.home hass[32258]: 2023-05-09 15:22:56.196 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:22:56 hass.home hass[32258]: 2023-05-09 15:22:56.245 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.193 seconds (success: False)
May 09 15:23:57 hass.home hass[32258]: 2023-05-09 15:23:57.292 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:23:57 hass.home hass[32258]: 2023-05-09 15:23:57.292 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.240 seconds (success: True)
May 09 15:24:57 hass.home hass[32258]: 2023-05-09 15:24:57.214 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:24:57 hass.home hass[32258]: 2023-05-09 15:24:57.262 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.210 seconds (success: False)
May 09 15:25:40 hass.home hass[32258]: 2023-05-09 15:25:40.563 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.629 seconds (success: True)
May 09 15:26:40 hass.home hass[32258]: 2023-05-09 15:26:40.388 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:26:40 hass.home hass[32258]: 2023-05-09 15:26:40.411 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.196 seconds (success: False)
May 09 15:27:41 hass.home hass[32258]: 2023-05-09 15:27:41.826 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:27:41 hass.home hass[32258]: 2023-05-09 15:27:41.827 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.611 seconds (success: True)
May 09 15:28:41 hass.home hass[32258]: 2023-05-09 15:28:41.372 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:28:41 hass.home hass[32258]: 2023-05-09 15:28:41.404 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.188 seconds (success: False)
May 09 15:29:42 hass.home hass[32258]: 2023-05-09 15:29:42.394 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:29:42 hass.home hass[32258]: 2023-05-09 15:29:42.395 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.179 seconds (success: True)
May 09 15:30:42 hass.home hass[32258]: 2023-05-09 15:30:42.374 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:30:42 hass.home hass[32258]: 2023-05-09 15:30:42.397 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.181 seconds (success: False)
May 09 15:31:43 hass.home hass[32258]: 2023-05-09 15:31:43.356 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:31:43 hass.home hass[32258]: 2023-05-09 15:31:43.356 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.140 seconds (success: True)
May 09 15:32:43 hass.home hass[32258]: 2023-05-09 15:32:43.375 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:32:43 hass.home hass[32258]: 2023-05-09 15:32:43.400 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.184 seconds (success: False)
May 09 15:33:44 hass.home hass[32258]: 2023-05-09 15:33:44.320 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:33:44 hass.home hass[32258]: 2023-05-09 15:33:44.321 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.104 seconds (success: True)
May 09 15:34:44 hass.home hass[32258]: 2023-05-09 15:34:44.365 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:34:44 hass.home hass[32258]: 2023-05-09 15:34:44.408 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.192 seconds (success: False)
May 09 15:35:45 hass.home hass[32258]: 2023-05-09 15:35:45.393 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:35:45 hass.home hass[32258]: 2023-05-09 15:35:45.394 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.179 seconds (success: True)
May 09 15:36:45 hass.home hass[32258]: 2023-05-09 15:36:45.378 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 09 15:36:45 hass.home hass[32258]: 2023-05-09 15:36:45.403 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.187 seconds (success: False)
May 09 15:37:46 hass.home hass[32258]: 2023-05-09 15:37:46.405 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home data recovered
May 09 15:37:46 hass.home hass[32258]: 2023-05-09 15:37:46.405 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.190 seconds (success: True)

Additional information

I'd suggest to ass some timeout after which the controller will be marked as unavailable. Until that the locally cached data will be used.

@home-assistant
Copy link

home-assistant bot commented May 9, 2023

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

Code owner commands

Code owners of rainbird 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 rainbird Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)


rainbird documentation
rainbird source
(message by IssueLinks)

@allenporter
Copy link
Contributor

I was hoping that the move to using update coordinators would resolve this by having only a single caller.

Is this with other callers of the device or only home assistant?

Which device is this?

(I'm not seeing this fwiw)

@konikvranik
Copy link
Contributor Author

Only Home Assistant should be connecting to the device. The only second app I use is the android app from Rainbird, but this is disabled and I use it just for debugging.

My unit is ESP-RZXe

@allenporter
Copy link
Contributor

@konikvranik I am curios if you notice the same behavior when using the App where it fails that often. (I imagine you'd have to capture with the proxy to know). I was previously under the impression that this happens when there are multiple clients connecting to the device, so i am wondering why this happens. Are you familiar with other scenarios where the device rejects requests like this?

@konikvranik
Copy link
Contributor Author

Actually, when I enable the android app, the it connects without issues. Only the HA plugin complains for server unavailability.
I faced this issue with my custom integration already (https://github.com/konikvranik/hacs_rainbird). So I solved it by caching the state and failing just after some count of error responses or after some time of unavailability of the server, but not for the first wrong reply as the server seems to be to behave this way.

@allenporter
Copy link
Contributor

I wonder what is the difference between the app and home assistant. Is it just that it polls more often?

Home assistant used to make multiple requests at the same time and the client library would retry and also had state. It used to still fail all the time for me and go avail and unavailable even with the retries, and have errors in the logs. I then made home assistant stop sending the requests in parallel and took out the retries because it no longer ever fails anymore for me, and now it just uses a normal update coordinator letting home assistant handle all errors.

Maybe we should lower the poll frequency for that device if that device can't handle requests that often. Otherwise, I'd like to understand why that request type is failing.

One other idea is that maybe it is a specific request failing if there are multiple being sent. Perhaps we can turn up debug logging for other parts of the library that logs the request details.

@konikvranik
Copy link
Contributor Author

konikvranik commented May 14, 2023

So what logging should I enable?
And how could I reconfigure the pooling interval?

@allenporter
Copy link
Contributor

I think the interesting log messages are in pyrainbird.async_client and pyrainbird.encryption.

As for polling interval, i don't think we can configure that without additional code changes.

@konikvranik
Copy link
Contributor Author

OK, I enabled debug for pyrainbird; let's see what will happen. For now it's available, so just success responses are in the log.

What seems to by remarkable to me is some king of regularity in the (un)availability in the history:
image

@konikvranik
Copy link
Contributor Author

Here is the log with success and also failures: pyrainbird.log

@allenporter
Copy link
Contributor

In the log it seems to succeed, then fail 1 minute later, then succeed 1 minute later, then fail 1 minute later. Back and forth like that. It's always on the first request to get the current active stations.

It is entirely consistent. This definitely makes me think we should try to figure out the device behavior that works better, rather than adding in more retries.

Right now the update interval in homeassistant/components/rainbird/coordinator.py is set to 1 minute. Want to manually update and see if 2 works more consistently? (My impression is you're a developer on this integration, and are comfortable to try this out)

@konikvranik
Copy link
Contributor Author

I tried it but it doesn't look to help. Here is the log right after the HA restart:

May 16 07:19:41 hass.home hass[31380]: 2023-05-16 07:19:41.433 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 20.591 seconds (success: False)
May 16 07:19:41 hass.home hass[31380]: 2023-05-16 07:19:41.434 WARNING (MainThread) [homeassistant.config_entries] Config entry 'rainbird.home' for rainbird integration not ready yet; Retrying in background
May 16 07:20:12 hass.home hass[31380]: 2023-05-16 07:20:12.925 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 10.047 seconds (success: True)
May 16 07:22:13 hass.home hass[31380]: 2023-05-16 07:22:13.301 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
May 16 07:22:13 hass.home hass[31380]: 2023-05-16 07:22:13.330 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.193 seconds (success: False)
May 16 07:24:13 hass.home hass[31380]: 2023-05-16 07:24:13.289 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.152 seconds (success: False)
May 16 07:26:13 hass.home hass[31380]: 2023-05-16 07:26:13.287 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.150 seconds (success: False)
May 16 07:28:13 hass.home hass[31380]: 2023-05-16 07:28:13.293 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.157 seconds (success: False)
May 16 07:30:13 hass.home hass[31380]: 2023-05-16 07:30:13.287 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.150 seconds (success: False)
May 16 07:32:13 hass.home hass[31380]: 2023-05-16 07:32:13.302 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.166 seconds (success: False)
May 16 07:34:13 hass.home hass[31380]: 2023-05-16 07:34:13.307 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.171 seconds (success: False)
May 16 07:36:13 hass.home hass[31380]: 2023-05-16 07:36:13.137 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
May 16 07:36:13 hass.home hass[31380]: 2023-05-16 07:36:13.138 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
May 16 07:36:13 hass.home hass[31380]: 2023-05-16 07:36:13.139 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1684215373.1389205, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
May 16 07:36:13 hass.home hass[31380]: 2023-05-16 07:36:13.296 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.159 seconds (success: False)
May 16 07:38:13 hass.home hass[31380]: 2023-05-16 07:38:13.140 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
May 16 07:38:13 hass.home hass[31380]: 2023-05-16 07:38:13.141 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
May 16 07:38:13 hass.home hass[31380]: 2023-05-16 07:38:13.142 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1684215493.1420305, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
May 16 07:38:13 hass.home hass[31380]: 2023-05-16 07:38:13.318 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 0.177 seconds (success: False)
May 16 07:39:02 hass.home hass[31380]: 2023-05-16 07:39:02.665 DEBUG (MainThread) [pyrainbird.async_client] Request (AvailableStationsRequest): 0300
May 16 07:39:02 hass.home hass[31380]: 2023-05-16 07:39:02.665 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1684215542.6658232, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "0300", "length": 2}}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.197 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"8300FF000000"}, "id": 0}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.198 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 8300FF000000
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.198 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'AvailableStationsResponse', 'pageNumber': 0, 'setStations': 4278190080}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.199 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.200 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1684215543.199887, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.593 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0000000000"}, "id": 0}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.594 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0000000000
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.594 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 0}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.595 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.596 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1684215543.5960658, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.933 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.934 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.935 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.935 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
May 16 07:39:03 hass.home hass[31380]: 2023-05-16 07:39:03.936 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1684215543.936278, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
May 16 07:39:04 hass.home hass[31380]: 2023-05-16 07:39:04.283 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}
May 16 07:39:04 hass.home hass[31380]: 2023-05-16 07:39:04.284 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000
May 16 07:39:04 hass.home hass[31380]: 2023-05-16 07:39:04.284 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}
May 16 07:39:04 hass.home hass[31380]: 2023-05-16 07:39:04.285 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 1.621 seconds (success: True)

The last true is after I reloaded the integration.

I'll observe the behavior the whole day and then I'll report the result.

@konikvranik
Copy link
Contributor Author

konikvranik commented May 16, 2023

After changing the interval to 2 minutes, the intervals changed but it's still unstable (probably worst):
image

But reloading the integration helped to get it online. Is it possible that we don't close previous connection or leave the controller in some blocked state by previous request?

@allenporter
Copy link
Contributor

Thanks this is really interesting. I'm curious why requesting every two minutes would be more likely to leave the controller in a weir state. Is there something deterministic happening at the two minute mark?

Regarding closing the connection, the rainbird integration is using the default home assistant client session when creating the client

According to https://docs.aiohttp.org/en/stable/client_reference.html

Session encapsulates a connection pool (connector instance) and supports keepalives by default. Unless you are connecting to a large, unknown number of different servers over the lifetime of your application, it is suggested you use a single session for the lifetime of your application to benefit from connection pooling.

When making requests, the rainbird client library uses the request method (see async_client) which doesn't have any special options here.

The home assistant connector does support multiple connections per host.

So, to your point perhaps we can try a more conservative ClientSession tuned specifically for this device that does not allow multiple connections. I think the two possible options could be:

  • connect and disconnect immediately
  • connect and keep a single connection alive for > 1 minute so it gets an exclusive connection with the device

I'm thinking the rainbird app does the second one, since it will block out other hosts while the app is open. Home assistant probably should prefer the first to avoid blocking out the rainbird app.

@allenporter
Copy link
Contributor

I have confirmed the rainbird app sets http.keepAlive to true and http.maxConnectionsto1` which matches the behavior observed that it keeps one connection open and blocks everyone else out.

@konikvranik
Copy link
Contributor Author

Good catch. So we should assure that we either close connection in every case, or we reuse the same connection and call the server synchronously, right?

@konikvranik
Copy link
Contributor Author

BTW, Rainbird uses the JSON RPC v2 which is capable to call multiple methods in one request, so what about to aggregate the requests onto the batches and fire multiple of them in one request?

@allenporter
Copy link
Contributor

Yeah, the simplest thing is to limit connections to 1 so maybe we can start with that, then see if it's needed to close the connection.

Very cool on json V2. I can definitely experiment with that.

@allenporter
Copy link
Contributor

allenporter commented May 18, 2023

I did some testing with setting a limit of one connection per host, and noticed that it did close the connection right away. However, I then reverted the changed to see if I could observe mulitple connections open or a long lived connection open and noticed it was already closing them with the old code.

Maybe you can see if you can confirm that the connection is hanging open? Then we can have more conviction that this will fix the issue you're seeing (since in my case, i'm actually not seeing an issue)

My rainbird is 10.10.38.50 so on my home assistant dev machine I ran this command to see the connections and they close immediately:

$ watch -n 5 "netstat -an | grep 10.10.38.50.80"
Every 5.0s: netstat -an | grep 10.10.38.50.80                       hostname: Wed May 17 21:16:41 2023

tcp        0      0 10.10.21.4:56960        10.10.38.50:80          TIME_WAIT
tcp        0      0 10.10.21.4:56972        10.10.38.50:80          TIME_WAIT
tcp        0      0 10.10.21.4:56974        10.10.38.50:80          TIME_WAIT

But then when i sniff the connection, i see the server/device response with Connection: Close so maybe this device decides to close the connection itself, rather than relying on client behavior to close it:

$ sudo tcpdump -i eth0 host rainbird.mrv.thebends.org -n -X
21:18:11.460118 IP 10.10.38.50.80 > 10.10.21.4.47684: Flags [P.], seq 1:228, ack 413, win 1892, length 227: HTTP: HTTP/1.1 200 OK
	0x0000:  4500 010b 80f3 0000 ff06 eaaf 0a0a 2632  E.............&2
	0x0010:  0a0a 1504 0050 ba44 5aaa 6087 5f6c be60  .....P.DZ.`._l.`
	0x0020:  5018 0764 a9f8 0000 4854 5450 2f31 2e31  P..d....HTTP/1.1
	0x0030:  2032 3030 204f 4b0d 0a43 6f6e 6e65 6374  .200.OK..Connect
	0x0040:  696f 6e3a 2043 6c6f 7365 0d0a 436f 6e74  ion:.Close..Cont
	0x0050:  656e 742d 7479 7065 3a20 6170 706c 6963  ent-type:.applic
	0x0060:  6174 696f 6e2f 6f63 7465 742d 7374 7265  ation/octet-stre
	0x0070:  616d 0d0a 436f 6e74 656e 742d 6c65 6e67  am..Content-leng
	0x0080:  7468 3a20 3132 380d 0a0d 0ad6 5053 785b  th:.128.....PSx[

So if we see your device is not closing the connection then maybe that will be a hint that we need to close it...

@allenporter
Copy link
Contributor

I tried playing with jsonrpc 2.0 batching but have not had any luck yet. I tried to just send the same command twice and got an invalid request:

$ examples/rainbird_tool.py --log-level debug  get_available_stations 
DEBUG:pyrainbird.async_client:Request (AvailableStationsRequest): 0300
DEBUG:pyrainbird.async_client:Request: [{"jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "0300", "length": 2}, "id": 1684384038.4410315}, {"jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "0300", "length": 2}, "id": 1684384038.4410315}]
DEBUG:pyrainbird.async_client:Response: {"jsonrpc":"2.0", "error":{"code":-32600, "message":"Invalid request"}, "id":null }

@konikvranik
Copy link
Contributor Author

Be careful, the IDs must differ. That the identifier which matches request to the response. So the response with the same ID matches the method call in the request.

@allenporter
Copy link
Contributor

I had the same thought and also tried with an id+1 for second request and got the same result.

@konikvranik
Copy link
Contributor Author

Here is sequence of my 200 followed by 503:


08:00:04.380656 IP 192.168.0.20.80 > 192.168.0.6.56460: Flags [P.], seq 1:228, ack 415, win 1890, length 227: HTTP: HTTP/1.1 200 OK
        0x0000:  4500 010b c5c4 0000 ff06 73bd c0a8 0014  E.........s.....
        0x0010:  c0a8 0006 0050 dc8c 366e 3544 5dda b1c7  .....P..6n5D]...
        0x0020:  5018 0762 d733 0000 4854 5450 2f31 2e31  P..b.3..HTTP/1.1
        0x0030:  2032 3030 204f 4b0d 0a43 6f6e 6e65 6374  .200.OK..Connect
        0x0040:  696f 6e3a 2043 6c6f 7365 0d0a 436f 6e74  ion:.Close..Cont
        0x0050:  656e 742d 7479 7065 3a20 6170 706c 6963  ent-type:.applic
        0x0060:  6174 696f 6e2f 6f63 7465 742d 7374 7265  ation/octet-stre
        0x0070:  616d 0d0a 436f 6e74 656e 742d 6c65 6e67  am..Content-leng
        0x0080:  7468 3a20 3132 380d 0a0d 0ad6 5053 785b  th:.128.....PSx[
        0x0090:  66e9 070c fac2 e45e eac1 e040 571b 3670  f......^...@W.6p
        0x00a0:  2028 75e7 6751 fecb 2fdb e0a6 737b 7098  .(u.gQ../...s{p.
        0x00b0:  4fca 2a86 7b28 0440 0370 1e4c 2b99 22db  O.*.{(.@.p.L+.".
        0x00c0:  f266 c5c3 5c7d 7929 9da0 2d78 2456 6612  .f..\}y)..-x$Vf.
        0x00d0:  768c 329b c2c8 fdee 9b71 3a87 7781 5b2b  v.2......q:.w.[+
        0x00e0:  e8db 784d 0f2e 1a6c 1ec4 a4cb 7398 ee6b  ..xM...l....s..k
        0x00f0:  d08b c32a 9734 0015 757d 094d e79b 0151  ...*.4..u}.M...Q
        0x0100:  9dd2 0286 a502 9703 ef41 e5              .........A.
08:00:04.380793 IP 192.168.0.6.56460 > 192.168.0.20.80: Flags [.], ack 228, win 64013, length 0
        0x0000:  4500 0028 005f 4000 4006 b906 c0a8 0006  E..(._@.@.......
        0x0010:  c0a8 0014 dc8c 0050 5dda b1c7 366e 3627  .......P]...6n6'
        0x0020:  5010 fa0d 8185 0000                      P.......
08:00:04.383307 IP 192.168.0.20.80 > 192.168.0.6.56460: Flags [F.], seq 228, ack 415, win 1890, length 0
        0x0000:  4500 0028 c5c5 0000 ff06 749f c0a8 0014  E..(......t.....
        0x0010:  c0a8 0006 0050 dc8c 366e 3627 5dda b1c7  .....P..6n6']...
        0x0020:  5011 0762 cdf2 0000 0000 0000 0000       P..b..........
08:00:04.391532 IP 192.168.0.6.56460 > 192.168.0.20.80: Flags [F.], seq 415, ack 229, win 64013, length 0
        0x0000:  4500 0028 0060 4000 4006 b905 c0a8 0006  E..(.`@.@.......
        0x0010:  c0a8 0014 dc8c 0050 5dda b1c7 366e 3628  .......P]...6n6(
        0x0020:  5011 fa0d 8185 0000                      P.......
08:00:04.402011 IP 192.168.0.20.80 > 192.168.0.6.56460: Flags [.], ack 416, win 1889, length 0
        0x0000:  4500 0028 c5c6 0000 ff06 749e c0a8 0014  E..(......t.....
        0x0010:  c0a8 0006 0050 dc8c 366e 3628 5dda b1c8  .....P..6n6(]...
        0x0020:  5010 0761 cdf2 0000 0000 0000 0000       P..a..........
08:00:11.659658 IP 192.168.0.6.56464 > 192.168.0.20.80: Flags [S], seq 1937797510, win 64240, options [mss 1460,sackOK,TS val 4185728336 ecr 0,nop,wscale 7], length 0
        0x0000:  4500 003c 2ff4 4000 4006 895d c0a8 0006  E..</.@.@..]....
        0x0010:  c0a8 0014 dc90 0050 7380 7186 0000 0000  .......Ps.q.....
        0x0020:  a002 faf0 8199 0000 0204 05b4 0402 080a  ................
        0x0030:  f97d 2550 0000 0000 0103 0307            .}%P........
08:00:11.663230 IP 192.168.0.20.80 > 192.168.0.6.56464: Flags [S.], seq 915046374, ack 1937797511, win 2304, options [mss 1152], length 0
        0x0000:  4500 002c c5c7 0000 ff06 7499 c0a8 0014  E..,......t.....
        0x0010:  c0a8 0006 0050 dc90 368a 7fe6 7380 7187  .....P..6...s.q.
        0x0020:  6012 0900 9686 0000 0204 0480 0000       `.............
08:00:11.663330 IP 192.168.0.6.56464 > 192.168.0.20.80: Flags [.], ack 1, win 64240, length 0
        0x0000:  4500 0028 2ff5 4000 4006 8970 c0a8 0006  E..(/.@.@..p....
        0x0010:  c0a8 0014 dc90 0050 7380 7187 368a 7fe7  .......Ps.q.6...
        0x0020:  5010 faf0 8185 0000                      P.......
08:00:11.663428 IP 192.168.0.6.56464 > 192.168.0.20.80: Flags [R.], seq 1, ack 1, win 64240, length 0
        0x0000:  4500 0028 2ff6 4000 4006 896f c0a8 0006  E..(/.@.@..o....
        0x0010:  c0a8 0014 dc90 0050 7380 7187 368a 7fe7  .......Ps.q.6...
        0x0020:  5014 faf0 8185 0000                      P.......
08:00:18.989412 IP 192.168.0.6.59616 > 192.168.0.20.55555: UDP, length 0
        0x0000:  4500 001c 6605 4000 4011 5361 c0a8 0006  E...f.@.@.Sa....
        0x0010:  c0a8 0014 e8e0 d903 0008 8184            ............
08:00:18.994858 IP 192.168.0.20 > 192.168.0.6: ICMP 192.168.0.20 udp port 55555 unreachable, length 36
        0x0000:  4500 0038 c5d2 0000 ff01 7487 c0a8 0014  E..8......t.....
        0x0010:  c0a8 0006 0303 7e81 0000 0000 4500 001c  ......~.....E...
        0x0020:  6605 4000 4011 5361 c0a8 0006 c0a8 0014  f.@.@.Sa........
        0x0030:  e8e0 d903 0008 bc8e                      ........
08:00:24.248771 IP 192.168.0.6.49228 > 192.168.0.20.80: Flags [S], seq 1699912461, win 64240, options [mss 1460,sackOK,TS val 4185740925 ecr 0,nop,wscale 7], length 0
        0x0000:  4500 003c 3622 4000 4006 832f c0a8 0006  E..<6"@.@../....
        0x0010:  c0a8 0014 c04c 0050 6552 9b0d 0000 0000  .....L.PeR......
        0x0020:  a002 faf0 8199 0000 0204 05b4 0402 080a  ................
        0x0030:  f97d 567d 0000 0000 0103 0307            .}V}........
08:00:24.376128 IP 192.168.0.20.80 > 192.168.0.6.49228: Flags [S.], seq 924316960, ack 1699912462, win 2304, options [mss 1152], length 0
        0x0000:  4500 002c c5dd 0000 ff06 7483 c0a8 0014  E..,......t.....
        0x0010:  c0a8 0006 0050 c04c 3717 f520 6552 9b0e  .....P.L7...eR..
        0x0020:  6012 0900 21aa 0000 0204 0480 0000       `...!.........
08:00:24.376265 IP 192.168.0.6.49228 > 192.168.0.20.80: Flags [.], ack 1, win 64240, length 0
        0x0000:  4500 0028 3623 4000 4006 8342 c0a8 0006  E..(6#@.@..B....
        0x0010:  c0a8 0014 c04c 0050 6552 9b0e 3717 f521  .....L.PeR..7..!
        0x0020:  5010 faf0 8185 0000                      P.......
08:00:24.378012 IP 192.168.0.6.49228 > 192.168.0.20.80: Flags [P.], seq 1:255, ack 1, win 64240, length 254: HTTP: POST /stick HTTP/1.1
        0x0000:  4500 0126 3624 4000 4006 8243 c0a8 0006  E..&6$@.@..C....
        0x0010:  c0a8 0014 c04c 0050 6552 9b0e 3717 f521  .....L.PeR..7..!
        0x0020:  5018 faf0 8283 0000 504f 5354 202f 7374  P.......POST./st
        0x0030:  6963 6b20 4854 5450 2f31 2e31 0d0a 486f  ick.HTTP/1.1..Ho
        0x0040:  7374 3a20 7261 696e 6269 7264 2e68 6f6d  st:.rainbird.hom
        0x0050:  650d 0a55 7365 722d 4167 656e 743a 2052  e..User-Agent:.R
        0x0060:  6169 6e42 6972 642f 322e 3020 4346 4e65  ainBird/2.0.CFNe
        0x0070:  7477 6f72 6b2f 3831 312e 352e 3420 4461  twork/811.5.4.Da
        0x0080:  7277 696e 2f31 362e 372e 300d 0a41 6363  rwin/16.7.0..Acc
        0x0090:  6570 742d 4c61 6e67 7561 6765 3a20 656e  ept-Language:.en
        0x00a0:  0d0a 4163 6365 7074 2d45 6e63 6f64 696e  ..Accept-Encodin
        0x00b0:  673a 2067 7a69 702c 2064 6566 6c61 7465  g:.gzip,.deflate
        0x00c0:  0d0a 4163 6365 7074 3a20 2a2f 2a0d 0a43  ..Accept:.*/*..C
        0x00d0:  6f6e 6e65 6374 696f 6e3a 206b 6565 702d  onnection:.keep-
        0x00e0:  616c 6976 650d 0a43 6f6e 7465 6e74 2d54  alive..Content-T
        0x00f0:  7970 653a 2061 7070 6c69 6361 7469 6f6e  ype:.application
        0x0100:  2f6f 6374 6574 2d73 7472 6561 6d0d 0a43  /octet-stream..C
        0x0110:  6f6e 7465 6e74 2d4c 656e 6774 683a 2031  ontent-Length:.1
        0x0120:  3630 0d0a 0d0a                           60....
08:00:24.378467 IP 192.168.0.6.49228 > 192.168.0.20.80: Flags [P.], seq 255:415, ack 1, win 64240, length 160: HTTP
        0x0000:  4500 00c8 3625 4000 4006 82a0 c0a8 0006  E...6%@.@.......
        0x0010:  c0a8 0014 c04c 0050 6552 9c0c 3717 f521  .....L.PeR..7..!
        0x0020:  5018 faf0 8225 0000 fc76 196f af6b 5559  P....%...v.o.kUY
        0x0030:  9c7d 68e9 7090 9d12 fa1a df45 b900 df7e  .}h.p......E...~
        0x0040:  4b5b a941 c139 7432 ec2e 8028 a068 704f  K[.A.9t2...(.hpO
        0x0050:  afc2 c6c6 6e70 6b5f e053 8a8a c971 f5b8  ....npk_.S...q..
        0x0060:  1923 be56 3666 3100 6ecf f467 0101 b330  .#.V6f1.n..g...0
        0x0070:  c383 1a92 04ef 882d deaa 38a4 163c 2612  .......-..8..<&.
        0x0080:  5ff3 a2ca 3a77 ac2b a6c4 77e7 ab46 2d23  _...:w.+..w..F-#
        0x0090:  f950 98b8 4103 9a01 56d9 1f59 58ea afb4  .P..A...V..YX...
        0x00a0:  582d 9383 426f 47dc e3de 53d3 4cd6 2578  X-..BoG...S.L.%x
        0x00b0:  095b 036e bf22 e1e0 386d 2148 6c77 c498  .[.n."..8m!Hlw..
        0x00c0:  065f c8aa 77b8 e28f                      ._..w...
08:00:24.381869 IP 192.168.0.20.80 > 192.168.0.6.49228: Flags [.], ack 415, win 1890, length 0
        0x0000:  4500 0028 c5de 0000 ff06 7486 c0a8 0014  E..(......t.....
        0x0010:  c0a8 0006 0050 c04c 3717 f521 6552 9cac  .....P.L7..!eR..
        0x0020:  5010 0762 3833 0000 0000 0000 0000       P..b83........
08:00:24.481453 IP 192.168.0.20.80 > 192.168.0.6.49228: Flags [P.], seq 1:80, ack 415, win 1890, length 79: HTTP: HTTP/1.1 503 Service Unavailable
        0x0000:  4500 0077 c5df 0000 ff06 7436 c0a8 0014  E..w......t6....
        0x0010:  c0a8 0006 0050 c04c 3717 f521 6552 9cac  .....P.L7..!eR..
        0x0020:  5018 0762 e869 0000 4854 5450 2f31 2e31  P..b.i..HTTP/1.1
        0x0030:  2035 3033 2053 6572 7669 6365 2055 6e61  .503.Service.Una
        0x0040:  7661 696c 6162 6c65 0d0a 436f 6e6e 6563  vailable..Connec
        0x0050:  7469 6f6e 3a20 4b65 6570 2d41 6c69 7665  tion:.Keep-Alive
        0x0060:  0d0a 436f 6e74 656e 742d 6c65 6e67 7468  ..Content-length
        0x0070:  3a20 300d 0a0d 0a                        :.0....

I don't see any connection closing there.

@konikvranik
Copy link
Contributor Author

I had the same thought and also tried with an id+1 for second request and got the same result.

Which means that they just say the use JSON RPC 2.0, but the don't. Sending of multiple methods must be supported by JSON RPC compliant server.
But never mind. Let's focus on connection closing.

BTW, what about to not send the keep-alive header?

@konikvranik
Copy link
Contributor Author

I tried to remove the keep-alive header, but it didn't helped to solve the issue.

@allenporter
Copy link
Contributor

Do you see the connections open in netstat after the first run?

@mdvz0r
Copy link

mdvz0r commented May 27, 2023

hi, i'm having the same issue.

In the home-assistant logs i see

2023-05-27 13:38:27.012 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall switch.turn_off (c:01H1EG0XBQXWXY0JAK63HR1WN6): entity_id=['switch.zone_X', 'switch.zone_Y']>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 98, in request
    resp.raise_for_status()
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://192.168.88.12/stick')

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1867, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1889, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 226, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 798, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 980, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/rainbird/switch.py", line 96, in async_turn_off
    await self.coordinator.controller.stop_irrigation()
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 289, in stop_irrigation
    await self._process_command(lambda resp: True, "StopIrrigationRequest")
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 437, in _process_command
    decrypted_data = await self._tunnelSip(
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 424, in _tunnelSip
    result = await self._local_client.request(
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 101, in request
    raise RainbirdDeviceBusyException(
pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
2023-05-27 13:39:28.896 ERROR (SyncWorker_6) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 95, in request
    resp = await self._websession.request(
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client.py", line 560, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_reqrep.py", line 899, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
  File "/usr/local/lib/python3.10/site-packages/aiohttp/streams.py", line 616, in read
    await self._waiter
aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 980, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/rainbird/switch.py", line 96, in async_turn_off
    await self.coordinator.controller.stop_irrigation()
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 289, in stop_irrigation
    await self._process_command(lambda resp: True, "StopIrrigationRequest")
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 437, in _process_command
    decrypted_data = await self._tunnelSip(
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 424, in _tunnelSip
    result = await self._local_client.request(
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 110, in request
    raise RainbirdApiException(
pyrainbird.exceptions.RainbirdApiException: Error communicating with device: Server disconnected
2023-05-27 13:39:28.922 ERROR (SyncWorker_6) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 95, in request
    resp = await self._websession.request(
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client.py", line 560, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/client_reqrep.py", line 899, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
  File "/usr/local/lib/python3.10/site-packages/aiohttp/streams.py", line 616, in read
    await self._waiter
aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 980, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 838, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/rainbird/switch.py", line 96, in async_turn_off
    await self.coordinator.controller.stop_irrigation()
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 289, in stop_irrigation
    await self._process_command(lambda resp: True, "StopIrrigationRequest")
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 437, in _process_command
    decrypted_data = await self._tunnelSip(
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 424, in _tunnelSip
    result = await self._local_client.request(
  File "/usr/local/lib/python3.10/site-packages/pyrainbird/async_client.py", line 110, in request
    raise RainbirdApiException(
pyrainbird.exceptions.RainbirdApiException: Error communicating with device: Server disconnected

In the meanwhile I don't see related active connections using:

b108f8363180:/config# netstat -an
Active Internet connections (servers and established)

is there a work around for the time being?

allenporter added a commit to allenporter/pyrainbird that referenced this issue Jul 15, 2023
@dffffffff
Copy link

Home Assistant 2023.7.2
ESP-ME3
Firmware: 2.12

Not sure if this is of any help but my irrigation automation failed earlier.

*********
2023-07-15 23:11:00.519 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-15 23:12:00.571 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.163 seconds (success: True)
2023-07-15 23:13:00.520 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.112 seconds (success: True)
2023-07-15 23:14:00.548 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.140 seconds (success: True)
2023-07-15 23:15:01.304 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home.lan data: Error communicating with Device: Device is busy; Wait 1 minute
2023-07-15 23:15:01.305 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.792 seconds (success: False)
2023-07-15 23:15:02.046 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 1.638 seconds (success: False)
2023-07-15 23:16:02.517 INFO (MainThread) [homeassistant.components.rainbird.coordinator] Fetching rainbird.home.lan data recovered
2023-07-15 23:16:02.517 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.109 seconds (success: True)
2023-07-15 23:17:02.518 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-15 23:18:02.519 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)

**********
2023-07-16 01:12:01.519 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-16 01:13:01.517 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.109 seconds (success: True)
2023-07-16 01:14:01.518 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-16 01:15:01.618 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.210 seconds (success: True)
2023-07-16 01:15:02.441 ERROR (MainThread) [homeassistant.components.automation.irrigation_rabatter] Irrigation: Error executing script. Unexpected error for call_service at pos 9: Device is busy; Wait 1 minute
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 120, in request
    resp.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://rainbird.home.lan/stick')

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 1965, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2005, in _execute_service
    return await cast(
           ^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 866, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 848, in entity_service_call
    response_data = task.result()  # pop exception if have
                    ^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1192, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 892, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/rainbird/switch.py", line 89, in async_turn_on
    await self.coordinator.controller.irrigate_zone(
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 313, in irrigate_zone
    await self._process_command(
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 467, in _process_command
    decrypted_data = await self._tunnelSip(
                     ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 454, in _tunnelSip
    result = await self._local_client.request(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 123, in request
    raise RainbirdDeviceBusyException(
pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
2023-07-16 01:15:02.448 ERROR (MainThread) [homeassistant.components.automation.irrigation_rabatter] While executing automation automation.irrigation_rabatter
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 120, in request
    resp.raise_for_status()
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 1005, in raise_for_status
    raise ClientResponseError(
aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://rainbird.home.lan/stick')

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

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 659, in async_trigger
    await self.action_script.async_run(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1569, in async_run
    return await asyncio.shield(run.async_run())
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 420, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 470, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 493, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 468, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 703, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 665, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 1965, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2005, in _execute_service
    return await cast(
           ^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 866, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 848, in entity_service_call
    response_data = task.result()  # pop exception if have
                    ^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1192, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 892, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/rainbird/switch.py", line 89, in async_turn_on
    await self.coordinator.controller.irrigate_zone(
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 313, in irrigate_zone
    await self._process_command(
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 467, in _process_command
    decrypted_data = await self._tunnelSip(
                     ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 454, in _tunnelSip
    result = await self._local_client.request(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyrainbird/async_client.py", line 123, in request
    raise RainbirdDeviceBusyException(
pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
2023-07-16 01:16:01.518 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-16 01:17:01.518 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-16 01:18:01.518 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.110 seconds (success: True)
2023-07-16 01:19:01.519 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.111 seconds (success: True)
2023-07-16 01:20:01.523 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home.lan data in 0.115 seconds (success: True)

@allenporter
Copy link
Contributor

Hi, it needs to include debug information to be helpful at this point similar to the others we're discussing above.

@dffffffff
Copy link

dffffffff commented Jul 16, 2023

Hi, it needs to include debug information to be helpful at this point similar to the others we're discussing above.

How can i provide/enable more debug information besides what i have in my home assistant configuration file?

logger:
  default: warning
  logs:
    homeassistant.components.rainbird: debug

@allenporter
Copy link
Contributor

From these two posts
#92857 (comment)
#92857 (comment)

These are the interesting log components to also enable:

pyrainbird.async_client
pyrainbird.encryption
aiohttp_retry

(You can also enable it in the UI and it should enable for pyrainbird.)

@allenporter
Copy link
Contributor

@konikvranik up for giving this a try on 2023.07.03?

@konikvranik
Copy link
Contributor Author

Hi @allenporter, thank you for your patience. Now it report also aiohttp_retry in the log, but I'm afraid that the behavior is still the same:
image

here is excerpt from the log:

čec 23 21:34:12 hass.home hass[480]: 2023-07-23 21:34:12.765 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.home data in 2.581 seconds (success: True)
čec 23 21:36:52 hass.home hass[5000]: 2023-07-23 21:36:52.511 DEBUG (MainThread) [pyrainbird.async_client] Request (ModelAndVersionRequest): 02
čec 23 21:36:52 hass.home hass[5000]: 2023-07-23 21:36:52.511 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141012.5117874, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "02", "length": 1}}
čec 23 21:36:55 hass.home hass[5000]: 2023-07-23 21:36:55.870 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":5, "data":"8200030209"}, "id": 0}
čec 23 21:36:55 hass.home hass[5000]: 2023-07-23 21:36:55.871 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 8200030209
čec 23 21:36:55 hass.home hass[5000]: 2023-07-23 21:36:55.871 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'ModelAndVersionResponse', 'modelID': 3, 'protocolRevisionMajor': 2, 'protocolRevisionMinor': 9}
čec 23 21:36:55 hass.home hass[5000]: 2023-07-23 21:36:55.872 DEBUG (MainThread) [pyrainbird.async_client] Request (AvailableStationsRequest): 0300
čec 23 21:36:55 hass.home hass[5000]: 2023-07-23 21:36:55.872 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141015.872663, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "0300", "length": 2}}
čec 23 21:36:55 hass.home hass[5000]: 2023-07-23 21:36:55.874 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:37:00 hass.home hass[5000]: 2023-07-23 21:37:00.878 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"8300FF000000"}, "id": 0}
čec 23 21:37:00 hass.home hass[5000]: 2023-07-23 21:37:00.879 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 8300FF000000
čec 23 21:37:00 hass.home hass[5000]: 2023-07-23 21:37:00.879 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'AvailableStationsResponse', 'pageNumber': 0, 'setStations': 4278190080}
čec 23 21:37:00 hass.home hass[5000]: 2023-07-23 21:37:00.879 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 21:37:00 hass.home hass[5000]: 2023-07-23 21:37:00.880 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141020.8801208, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 21:37:00 hass.home hass[5000]: 2023-07-23 21:37:00.882 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:37:03 hass.home hass[5000]: 2023-07-23 21:37:03.541 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0000000000"}, "id": 0}
čec 23 21:37:03 hass.home hass[5000]: 2023-07-23 21:37:03.542 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0000000000
čec 23 21:37:03 hass.home hass[5000]: 2023-07-23 21:37:03.542 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 0}
čec 23 21:37:03 hass.home hass[5000]: 2023-07-23 21:37:03.542 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 21:37:03 hass.home hass[5000]: 2023-07-23 21:37:03.543 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141023.543014, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 21:37:03 hass.home hass[5000]: 2023-07-23 21:37:03.545 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:37:12 hass.home hass[5000]: 2023-07-23 21:37:12.558 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
čec 23 21:37:12 hass.home hass[5000]: 2023-07-23 21:37:12.559 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
čec 23 21:37:12 hass.home hass[5000]: 2023-07-23 21:37:12.559 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}
čec 23 21:37:12 hass.home hass[5000]: 2023-07-23 21:37:12.559 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 21:37:12 hass.home hass[5000]: 2023-07-23 21:37:12.560 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141032.5599701, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 21:37:12 hass.home hass[5000]: 2023-07-23 21:37:12.583 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:37:17 hass.home hass[5000]: 2023-07-23 21:37:17.248 WARNING (MainThread) [homeassistant.config_entries] Config entry 'rainbird.home' for rainbird integration not ready yet; Retrying in background
čec 23 21:37:57 hass.home hass[5000]: 2023-07-23 21:37:57.629 DEBUG (MainThread) [pyrainbird.async_client] Request (ModelAndVersionRequest): 02
čec 23 21:37:57 hass.home hass[5000]: 2023-07-23 21:37:57.630 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141077.6297152, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "02", "length": 1}}
čec 23 21:38:03 hass.home hass[5000]: 2023-07-23 21:38:03.195 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":5, "data":"8200030209"}, "id": 0}
čec 23 21:38:03 hass.home hass[5000]: 2023-07-23 21:38:03.196 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 8200030209
čec 23 21:38:03 hass.home hass[5000]: 2023-07-23 21:38:03.196 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'ModelAndVersionResponse', 'modelID': 3, 'protocolRevisionMajor': 2, 'protocolRevisionMinor': 9}
čec 23 21:38:03 hass.home hass[5000]: 2023-07-23 21:38:03.197 DEBUG (MainThread) [pyrainbird.async_client] Request (AvailableStationsRequest): 0300
čec 23 21:38:03 hass.home hass[5000]: 2023-07-23 21:38:03.197 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141083.1977901, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "0300", "length": 2}}
čec 23 21:38:03 hass.home hass[5000]: 2023-07-23 21:38:03.231 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:38:04 hass.home hass[5000]: 2023-07-23 21:38:04.680 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"8300FF000000"}, "id": 0}
čec 23 21:38:04 hass.home hass[5000]: 2023-07-23 21:38:04.680 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 8300FF000000
čec 23 21:38:04 hass.home hass[5000]: 2023-07-23 21:38:04.681 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'AvailableStationsResponse', 'pageNumber': 0, 'setStations': 4278190080}
čec 23 21:38:04 hass.home hass[5000]: 2023-07-23 21:38:04.681 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 21:38:04 hass.home hass[5000]: 2023-07-23 21:38:04.681 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141084.681786, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 21:38:04 hass.home hass[5000]: 2023-07-23 21:38:04.692 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:38:09 hass.home hass[5000]: 2023-07-23 21:38:09.378 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0000000000"}, "id": 0}
čec 23 21:38:09 hass.home hass[5000]: 2023-07-23 21:38:09.378 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0000000000
čec 23 21:38:09 hass.home hass[5000]: 2023-07-23 21:38:09.379 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 0}
čec 23 21:38:09 hass.home hass[5000]: 2023-07-23 21:38:09.379 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 21:38:09 hass.home hass[5000]: 2023-07-23 21:38:09.380 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141089.3798363, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 21:38:09 hass.home hass[5000]: 2023-07-23 21:38:09.392 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:38:10 hass.home hass[5000]: 2023-07-23 21:38:10.650 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
čec 23 21:38:10 hass.home hass[5000]: 2023-07-23 21:38:10.650 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
čec 23 21:38:10 hass.home hass[5000]: 2023-07-23 21:38:10.651 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}
čec 23 21:38:10 hass.home hass[5000]: 2023-07-23 21:38:10.651 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 21:38:10 hass.home hass[5000]: 2023-07-23 21:38:10.651 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141090.6516793, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 21:38:10 hass.home hass[5000]: 2023-07-23 21:38:10.662 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:38:12 hass.home hass[5000]: 2023-07-23 21:38:12.761 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}
čec 23 21:38:12 hass.home hass[5000]: 2023-07-23 21:38:12.762 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000
čec 23 21:38:12 hass.home hass[5000]: 2023-07-23 21:38:12.762 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}
čec 23 21:39:13 hass.home hass[5000]: 2023-07-23 21:39:13.258 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 21:39:13 hass.home hass[5000]: 2023-07-23 21:39:13.258 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 21:39:13 hass.home hass[5000]: 2023-07-23 21:39:13.259 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141153.2592258, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 21:39:13 hass.home hass[5000]: 2023-07-23 21:39:13.263 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.037 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0000000000"}, "id": 0}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.038 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0000000000
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.038 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 0}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.038 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.039 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141154.038898, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.041 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.776 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.776 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.777 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.777 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.778 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141154.7780545, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.780 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.797 DEBUG (MainThread) [pyrainbird.async_client] Request (ManuallyRunStationRequest): 39000306
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.798 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141154.798464, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "39000306", "length": 4}}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.804 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3

@allenporter
Copy link
Contributor

@konikvranik thank you, would you mind include a little more detail? It doesn't appear to be showing details about the update coordinator successes and failures like before.

@konikvranik
Copy link
Contributor Author

konikvranik commented Jul 24, 2023

I'm sorry @allenporter, I included just the beginning after restart. Here is excerpt with the errors:

čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.777 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.778 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141154.7780545, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.780 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.797 DEBUG (MainThread) [pyrainbird.async_client] Request (ManuallyRunStationRequest): 39000306
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.798 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141154.798464, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "39000306", "length": 4}}
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.804 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:14 hass.home hass[5000]: 2023-07-23 21:39:14.919 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:39:15 hass.home hass[5000]: 2023-07-23 21:39:15.687 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}
čec 23 21:39:15 hass.home hass[5000]: 2023-07-23 21:39:15.687 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000
čec 23 21:39:15 hass.home hass[5000]: 2023-07-23 21:39:15.687 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}
čec 23 21:39:17 hass.home hass[5000]: 2023-07-23 21:39:17.233 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:39:17 hass.home hass[5000]: 2023-07-23 21:39:17.251 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:39:19 hass.home hass[5000]: 2023-07-23 21:39:19.734 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:39:19 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 120, in request
čec 23 21:39:19 hass.home hass[5000]: aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://rainbird.home/stick')
čec 23 21:39:19 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/homeassistant/components/rainbird/switch.py", line 89, in async_turn_on
čec 23 21:39:19 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 313, in irrigate_zone
čec 23 21:39:19 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 467, in _process_command
čec 23 21:39:19 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 454, in _tunnelSip
čec 23 21:39:19 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 123, in request
čec 23 21:39:19 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
čec 23 21:39:44 hass.home hass[5000]: 2023-07-23 21:39:44.419 DEBUG (MainThread) [pyrainbird.async_client] Request (ManuallyRunStationRequest): 39000306
čec 23 21:39:44 hass.home hass[5000]: 2023-07-23 21:39:44.420 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141184.4199245, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "39000306", "length": 4}}
čec 23 21:39:44 hass.home hass[5000]: 2023-07-23 21:39:44.425 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.202 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"0139"}, "id": 0}
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.203 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 0139
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.204 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'AcknowledgeResponse', 'commandEcho': 57}
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.207 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.208 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.208 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141185.2086146, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.210 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.966 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0004000000"}, "id": 0}
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.966 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0004000000
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.966 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 67108864}
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.967 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.967 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141185.9672515, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 21:39:45 hass.home hass[5000]: 2023-07-23 21:39:45.969 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:46 hass.home hass[5000]: 2023-07-23 21:39:46.753 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
čec 23 21:39:46 hass.home hass[5000]: 2023-07-23 21:39:46.753 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
čec 23 21:39:46 hass.home hass[5000]: 2023-07-23 21:39:46.753 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}
čec 23 21:39:46 hass.home hass[5000]: 2023-07-23 21:39:46.754 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 21:39:46 hass.home hass[5000]: 2023-07-23 21:39:46.754 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141186.7543142, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 21:39:46 hass.home hass[5000]: 2023-07-23 21:39:46.755 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:39:47 hass.home hass[5000]: 2023-07-23 21:39:47.526 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}
čec 23 21:39:47 hass.home hass[5000]: 2023-07-23 21:39:47.526 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000
čec 23 21:39:47 hass.home hass[5000]: 2023-07-23 21:39:47.527 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}
čec 23 21:40:03 hass.home hass[5000]: 2023-07-23 21:40:03.053 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:03 hass.home hass[5000]: 2023-07-23 21:40:03.054 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141203.0542946, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "40", "length": 1}}
čec 23 21:40:03 hass.home hass[5000]: 2023-07-23 21:40:03.058 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:03 hass.home hass[5000]: 2023-07-23 21:40:03.470 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:05 hass.home hass[5000]: 2023-07-23 21:40:05.687 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:05 hass.home hass[5000]: 2023-07-23 21:40:05.699 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:08 hass.home hass[5000]: 2023-07-23 21:40:08.401 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:08 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 120, in request
čec 23 21:40:08 hass.home hass[5000]: aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://rainbird.home/stick')
čec 23 21:40:08 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/homeassistant/components/rainbird/switch.py", line 97, in async_turn_off
čec 23 21:40:08 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 319, in stop_irrigation
čec 23 21:40:08 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 467, in _process_command
čec 23 21:40:08 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 454, in _tunnelSip
čec 23 21:40:08 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 123, in request
čec 23 21:40:08 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
čec 23 21:40:11 hass.home hass[5000]: 2023-07-23 21:40:11.839 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:11 hass.home hass[5000]: 2023-07-23 21:40:11.840 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141211.840193, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "40", "length": 1}}
čec 23 21:40:11 hass.home hass[5000]: 2023-07-23 21:40:11.843 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:11 hass.home hass[5000]: 2023-07-23 21:40:11.859 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:15 hass.home hass[5000]: 2023-07-23 21:40:15.443 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:15 hass.home hass[5000]: 2023-07-23 21:40:15.473 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:16 hass.home hass[5000]: 2023-07-23 21:40:16.517 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:16 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 120, in request
čec 23 21:40:16 hass.home hass[5000]: aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://rainbird.home/stick')
čec 23 21:40:16 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/homeassistant/components/rainbird/switch.py", line 97, in async_turn_off
čec 23 21:40:16 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 319, in stop_irrigation
čec 23 21:40:16 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 467, in _process_command
čec 23 21:40:16 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 454, in _tunnelSip
čec 23 21:40:16 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 123, in request
čec 23 21:40:16 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
čec 23 21:40:22 hass.home hass[5000]: 2023-07-23 21:40:22.262 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:22 hass.home hass[5000]: 2023-07-23 21:40:22.262 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141222.2627852, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "40", "length": 1}}
čec 23 21:40:22 hass.home hass[5000]: 2023-07-23 21:40:22.267 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:22 hass.home hass[5000]: 2023-07-23 21:40:22.276 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:24 hass.home hass[5000]: 2023-07-23 21:40:24.774 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:24 hass.home hass[5000]: 2023-07-23 21:40:24.784 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:25 hass.home hass[5000]: 2023-07-23 21:40:25.189 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:25 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 120, in request
čec 23 21:40:25 hass.home hass[5000]: aiohttp.client_exceptions.ClientResponseError: 503, message='Service Unavailable', url=URL('http://rainbird.home/stick')
čec 23 21:40:25 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/homeassistant/components/rainbird/switch.py", line 97, in async_turn_off
čec 23 21:40:25 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 319, in stop_irrigation
čec 23 21:40:25 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 467, in _process_command
čec 23 21:40:25 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 454, in _tunnelSip
čec 23 21:40:25 hass.home hass[5000]:   File "/srv/homeassistant/lib/python3.11/site-packages/pyrainbird/async_client.py", line 123, in request
čec 23 21:40:25 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute
čec 23 21:40:30 hass.home hass[5000]: 2023-07-23 21:40:30.095 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:30 hass.home hass[5000]: 2023-07-23 21:40:30.096 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141230.096475, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "40", "length": 1}}
čec 23 21:40:30 hass.home hass[5000]: 2023-07-23 21:40:30.099 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:30 hass.home hass[5000]: 2023-07-23 21:40:30.123 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:31 hass.home hass[5000]: 2023-07-23 21:40:31.392 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:31 hass.home hass[5000]: 2023-07-23 21:40:31.424 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 21:40:34 hass.home hass[5000]: 2023-07-23 21:40:34.529 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.301 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"0140"}, "id": 0}
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.302 DEBUG (MainThread) [pyrainbird.async_client] Response from line: 0140
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.302 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'AcknowledgeResponse', 'commandEcho': 64}
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.304 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.304 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.305 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141235.3050156, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.306 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:36 hass.home hass[5000]: 2023-07-23 21:40:36.361 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0000000000"}, "id": 0}
čec 23 21:40:36 hass.home hass[5000]: 2023-07-23 21:40:36.362 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0000000000
čec 23 21:40:36 hass.home hass[5000]: 2023-07-23 21:40:36.362 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 0}
čec 23 21:40:36 hass.home hass[5000]: 2023-07-23 21:40:36.363 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 21:40:36 hass.home hass[5000]: 2023-07-23 21:40:36.363 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690141236.3637798, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 21:40:36 hass.home hass[5000]: 2023-07-23 21:40:36.365 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3

and another one:

čec 23 22:11:06 hass.home hass[5000]: 2023-07-23 22:11:06.910 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 22:11:06 hass.home hass[5000]: 2023-07-23 22:11:06.910 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143066.9103365, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 22:11:06 hass.home hass[5000]: 2023-07-23 22:11:06.912 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:11:07 hass.home hass[5000]: 2023-07-23 22:11:07.714 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}
čec 23 22:11:07 hass.home hass[5000]: 2023-07-23 22:11:07.715 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000
čec 23 22:11:07 hass.home hass[5000]: 2023-07-23 22:11:07.715 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}
čec 23 22:12:07 hass.home hass[5000]: 2023-07-23 22:12:07.686 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 22:12:07 hass.home hass[5000]: 2023-07-23 22:12:07.687 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 22:12:07 hass.home hass[5000]: 2023-07-23 22:12:07.687 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143127.6874728, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 22:12:07 hass.home hass[5000]: 2023-07-23 22:12:07.689 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:12:07 hass.home hass[5000]: 2023-07-23 22:12:07.871 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 22:12:10 hass.home hass[5000]: 2023-07-23 22:12:10.259 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 22:12:10 hass.home hass[5000]: 2023-07-23 22:12:10.279 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 22:12:12 hass.home hass[5000]: 2023-07-23 22:12:12.326 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 22:12:12 hass.home hass[5000]: 2023-07-23 22:12:12.355 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
čec 23 22:13:12 hass.home hass[5000]: 2023-07-23 22:13:12.258 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 22:13:12 hass.home hass[5000]: 2023-07-23 22:13:12.259 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 22:13:12 hass.home hass[5000]: 2023-07-23 22:13:12.259 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143192.2595148, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 22:13:12 hass.home hass[5000]: 2023-07-23 22:13:12.261 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.087 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0080000000"}, "id": 0}
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.088 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0080000000
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.088 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 2147483648}
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.089 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.089 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143193.0897, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.092 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.876 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.877 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.877 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.877 DEBUG (MainThread) [pyrainbird.async_client] Request (RainDelayGetRequest): 36
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.878 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143193.8780541, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "36", "length": 1}}
čec 23 22:13:13 hass.home hass[5000]: 2023-07-23 22:13:13.880 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:13:14 hass.home hass[5000]: 2023-07-23 22:13:14.679 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}
čec 23 22:13:14 hass.home hass[5000]: 2023-07-23 22:13:14.679 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000
čec 23 22:13:14 hass.home hass[5000]: 2023-07-23 22:13:14.680 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}
čec 23 22:14:14 hass.home hass[5000]: 2023-07-23 22:14:14.258 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 22:14:14 hass.home hass[5000]: 2023-07-23 22:14:14.259 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 22:14:14 hass.home hass[5000]: 2023-07-23 22:14:14.259 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143254.2595594, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 22:14:14 hass.home hass[5000]: 2023-07-23 22:14:14.261 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:14:14 hass.home hass[5000]: 2023-07-23 22:14:14.383 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 22:14:15 hass.home hass[5000]: 2023-07-23 22:14:15.648 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 22:14:15 hass.home hass[5000]: 2023-07-23 22:14:15.659 DEBUG (MainThread) [aiohttp_retry] Retrying after response code: 503
čec 23 22:14:16 hass.home hass[5000]: 2023-07-23 22:14:16.846 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 22:14:16 hass.home hass[5000]: 2023-07-23 22:14:16.871 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.home data: Error communicating with Device: Device is busy; Wait 1 minute
čec 23 22:15:16 hass.home hass[5000]: 2023-07-23 22:15:16.259 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'
čec 23 22:15:16 hass.home hass[5000]: 2023-07-23 22:15:16.260 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00
čec 23 22:15:16 hass.home hass[5000]: 2023-07-23 22:15:16.260 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143316.2604184, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}
čec 23 22:15:16 hass.home hass[5000]: 2023-07-23 22:15:16.266 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.047 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":6, "data":"BF0080000000"}, "id": 0}
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.048 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BF0080000000
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.048 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentStationsActiveResponse', 'pageNumber': 0, 'activeStations': 2147483648}
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.048 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentRainSensorStateRequest): 3E
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.049 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1690143317.0489779, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3E", "length": 1}}
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.052 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.939 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"BE00"}, "id": 0}
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.940 DEBUG (MainThread) [pyrainbird.async_client] Response from line: BE00
čec 23 22:15:17 hass.home hass[5000]: 2023-07-23 22:15:17.940 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'CurrentRainSensorStateResponse', 'sensorState': 0}

It seems that the stacktrace is present just in the first part of the log. All the rest is just like the second excerpt, just errors, no stacktraces.

@allenporter
Copy link
Contributor

Thanks, that is what I was looking for.

So we see it retrying three times now and all 3 times it gets a device busy error across 5 seconds, and the device still won't respond.

Are you sure nothing else is talking to the device? You don't have multiple home assistant instances polling it or anything? This is pretty odd that the device is.busy for so long.

What else? Should it try longer?

@konikvranik
Copy link
Contributor Author

konikvranik commented Jul 24, 2023

No other device connected to the rainbird should be present in my network. Only my single instance of HA and phone, but the app wasn't active. My experience is that when it's unavailable, it gets available in aprox 1 minute. So if we could use cached results for about one minute and also cache the start stop requests for this period and execute it when available, this could help IMHO.

@dffffffff
Copy link

From these two posts #92857 (comment) #92857 (comment)

These are the interesting log components to also enable:

pyrainbird.async_client
pyrainbird.encryption
aiohttp_retry

(You can also enable it in the UI and it should enable for pyrainbird.)

log.txt

Log file attached.

@allenporter
Copy link
Contributor

@dffffffff that shows a single failure when the device is busy, which is expected when the device is busy since it only supports a single request at a time. Are you seeing the same flip flopping back and for unavailable/available as the original issue?

@allenporter
Copy link
Contributor

@konikvranik in your latest example, it seems like there are many stop irrigation requests happening. Are you automating stop command retries yourself every 10-8 seconds? or were you interactively running those commands?

čec 23 21:40:03 hass.home hass[5000]: 2023-07-23 21:40:03.053 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
# retries 3 times:
-
čec 23 21:40:03 hass.home hass[5000]: 2023-07-23 21:40:03.058 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:05 hass.home hass[5000]: 2023-07-23 21:40:05.687 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:08 hass.home hass[5000]: 2023-07-23 21:40:08.401 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:08 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute

Then within 10 seconds there is another:

čec 23 21:40:11 hass.home hass[5000]: 2023-07-23 21:40:11.839 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:11 hass.home hass[5000]: 2023-07-23 21:40:11.843 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:15 hass.home hass[5000]: 2023-07-23 21:40:15.443 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:16 hass.home hass[5000]: 2023-07-23 21:40:16.517 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:16 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute

Then a few seconds later

čec 23 21:40:22 hass.home hass[5000]: 2023-07-23 21:40:22.262 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:22 hass.home hass[5000]: 2023-07-23 21:40:22.267 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:24 hass.home hass[5000]: 2023-07-23 21:40:24.774 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:25 hass.home hass[5000]: 2023-07-23 21:40:25.189 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:25 hass.home hass[5000]: pyrainbird.exceptions.RainbirdDeviceBusyException: Device is busy; Wait 1 minute

Then a few seconds later

čec 23 21:40:30 hass.home hass[5000]: 2023-07-23 21:40:30.095 DEBUG (MainThread) [pyrainbird.async_client] Request (StopIrrigationRequest): 40
čec 23 21:40:30 hass.home hass[5000]: 2023-07-23 21:40:30.099 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3
čec 23 21:40:31 hass.home hass[5000]: 2023-07-23 21:40:31.392 DEBUG (MainThread) [aiohttp_retry] Attempt 2 out of 3
čec 23 21:40:34 hass.home hass[5000]: 2023-07-23 21:40:34.529 DEBUG (MainThread) [aiohttp_retry] Attempt 3 out of 3
čec 23 21:40:35 hass.home hass[5000]: 2023-07-23 21:40:35.301 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":2, "data":"0140"}, "id": 0}

Then it succeeds. So from 21:40:03 to 21:40:35 the device is rejecting all stop commands. Even if we change home assistant to ignore failures and treat them like successes before marking the device unavailable on/off, it's still going to fundamentally reject these stop commands.

What do you experience with the Rainbird app when your device goes unavailable for the ~minute at a time? Is it also rejecting your requests?

One other idea I have is to shift the polling interval so that it lines up with device availability. e.g. maybe your device should only poll every 2 minutes and align to the times of availability.

@konikvranik
Copy link
Contributor Author

konikvranik commented Aug 12, 2023

I'm not aware of any automation regarding stopping.

I didn't try the app in sync with HA, but sometimes I experience also issue with connecting with the official app.

Regarding of the 2 min interval, I already tried it on the beginning, but it leaf to even worst lags.

@allenporter
Copy link
Contributor

allenporter commented Aug 12, 2023

I'm not aware of any automation regarding stopping.

Do you have any thoughts about why there may be different stop requests sent a few moments apart? Is this an automation sending stop to a few different sprinklers?

@dffffffff
Copy link

@allenporter still seeing this issue on Home Assistant 2023.8.2 - happens once or twice per 24 hours, the entities are marked as

became unavailable 09:02:33 - 33 minutes ago


2023-08-19 09:01:28.310 DEBUG (MainThread) [pyrainbird.async_client] Response: {"jsonrpc": "2.0", "result":{"length":3, "data":"B60000"}, "id": 0}

2023-08-19 09:01:28.310 DEBUG (MainThread) [pyrainbird.async_client] Response from line: B60000

2023-08-19 09:01:28.310 DEBUG (MainThread) [pyrainbird.async_client] Response: {'type': 'RainDelaySettingResponse', 'delaySetting': 0}

2023-08-19 09:01:28.311 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.lan.home data in 0.112 seconds (success: True)

2023-08-19 09:02:28.198 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'

2023-08-19 09:02:28.198 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00

2023-08-19 09:02:28.199 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1692428548.199015, "jsonrpc": "2.0", "method": "tunnelSip", "params": {"data": "3F00", "length": 2}}

2023-08-19 09:02:28.200 DEBUG (MainThread) [aiohttp_retry] Attempt 1 out of 3

2023-08-19 09:02:33.206 ERROR (MainThread) [homeassistant.components.rainbird.coordinator] Error fetching rainbird.lan.home data: Error communicating with Device: Error communicating with device: Cannot connect to host rainbird.lan.home:80 ssl:default [Try again]

2023-08-19 09:02:33.207 DEBUG (MainThread) [homeassistant.components.rainbird.coordinator] Finished fetching rainbird.lan.home data in 5.009 seconds (success: False)

2023-08-19 09:03:33.200 DEBUG (MainThread) [pyrainbird.async_client] Returned cached result for key 'AvailableStationsRequest-(0,)'

2023-08-19 09:03:33.200 DEBUG (MainThread) [pyrainbird.async_client] Request (CurrentStationsActiveRequest): 3F00

2023-08-19 09:03:33.200 DEBUG (MainThread) [pyrainbird.async_client] Request: {"id": 1692428613.2007148, "jsonrpc": "2.0", "method": "tunnelSip",```

@allenporter
Copy link
Contributor

@dffffffff that says it can't connect to your device so it probably has a poor wireless connection? This is working as intended (the device is unavailable) so it is correctly marking as unavailable and different from this issue where the device is rejecting the requests because it is busy.

@dffffffff
Copy link

@dffffffff that says it can't connect to your device so it probably has a poor wireless connection? This is working as intended (the device is unavailable) so it is correctly marking as unavailable and different from this issue where the device is rejecting the requests because it is busy.

I see, the wifi link module is literally less than a meter from the wifi access point, doubt the connection is poor but i guess that is for another issue/thread :)

@issue-triage-workflows
Copy link

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 has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

@issue-triage-workflows issue-triage-workflows bot closed this as not planned Won't fix, can't repro, duplicate, stale Nov 24, 2023
@github-actions github-actions bot locked and limited conversation to collaborators Dec 24, 2023
@allenporter
Copy link
Contributor

In #112146 further adjustments were made to limit to only a single connection.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants