Rain Bird functions, but blows up the log with error after error after error

Question

Rain Bird functions, but blows up the log with error after error after error

mikesalz opened this issue 5 years ago · 33 comments

mikesalz commented 5 years ago

The problem

The Rain Bird integration seems to work correctly, but writes hundreds of errors a day to the log.

Environment

Home Assistant Core release with the issue: 0.107.7
Last working Home Assistant Core release (if known): Not sure if ever?
Operating environment (Home Assistant/Supervised/Docker/venv): Docker on Synology
Integration causing this issue: Rainbird
Link to integration documentation on our website: https://www.home-assistant.io/integrations/rainbird/

Problem-relevant `configuration.yaml`

rainbird:
  - host: XXX.XXX.X.XXX
    password: XXXXXXXXX
    trigger_time: 20
    zones:
      1:
        friendly_name: Driveway Right Sprinklers
        trigger_time:
          minutes: 20
      2:
        friendly_name: Driveway Left Sprinklers
        trigger_time:
          minutes: 20
      3:
        friendly_name: Front Yard Sprinklers
        trigger_time:
          minutes: 20
      4:
        friendly_name: Side Yard Sprinklers
        trigger_time:
          minutes: 20
      5:
        friendly_name: Back Yard Sprinklers
        trigger_time:
          minutes: 20
      6:
        friendly_name: Unused Sprinkler Zone
        trigger_time:
          minutes: 1

Traceback/Error logs

2020-04-02 18:47:09 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.unused_sprinkler_zone is taking over 10 seconds
2020-04-02 18:47:30 WARNING (SyncWorker_1) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 18:47:40 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.back_yard_sprinklers is taking over 10 seconds
2020-04-02 18:52:08 WARNING (SyncWorker_3) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 18:52:17 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.front_yard_sprinklers is taking over 10 seconds
2020-04-02 18:59:51 WARNING (SyncWorker_18) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:00:01 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:00:01 WARNING (SyncWorker_18) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:01:24 WARNING (SyncWorker_7) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:01:34 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:02:58 WARNING (SyncWorker_3) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:03:07 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.front_yard_sprinklers is taking over 10 seconds
2020-04-02 19:09:40 WARNING (SyncWorker_19) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:09:50 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:10:43 WARNING (SyncWorker_0) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:10:52 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.driveway_left_sprinklers is taking over 10 seconds
2020-04-02 19:12:46 WARNING (SyncWorker_19) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:12:56 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:13:48 WARNING (SyncWorker_8) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:13:58 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:16:55 WARNING (SyncWorker_18) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:17:04 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.back_yard_sprinklers is taking over 10 seconds
2020-04-02 19:20:00 WARNING (SyncWorker_17) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:20:10 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.front_yard_sprinklers is taking over 10 seconds
2020-04-02 19:24:08 WARNING (SyncWorker_1) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:24:18 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:27:14 WARNING (SyncWorker_16) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:27:24 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.driveway_right_sprinklers is taking over 10 seconds
2020-04-02 19:32:25 WARNING (SyncWorker_3) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:32:34 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.back_yard_sprinklers is taking over 10 seconds
2020-04-02 19:48:56 WARNING (SyncWorker_5) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:49:06 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.unused_sprinkler_zone is taking over 10 seconds
2020-04-02 19:56:38 WARNING (SyncWorker_0) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:56:48 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 19:58:42 WARNING (SyncWorker_2) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 19:58:52 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 20:10:28 WARNING (MainThread) [homeassistant.core] Unable to remove unknown listener <function async_track_point_in_utc_time.<locals>.point_in_time_listener at 0x7fbb920ddcb0>
2020-04-02 20:14:10 WARNING (SyncWorker_6) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 20:14:20 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 20:17:47 WARNING (SyncWorker_19) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 20:17:57 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 20:18:18 WARNING (SyncWorker_1) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 20:18:28 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:08:22 WARNING (SyncWorker_18) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:08:32 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:16:38 WARNING (SyncWorker_13) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:16:48 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:20:15 WARNING (SyncWorker_9) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:20:25 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:21:17 WARNING (MainThread) [homeassistant.helpers.entity] Update of camera.front_door is taking over 10 seconds
2020-04-02 21:26:26 WARNING (SyncWorker_5) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:26:36 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:29:32 WARNING (SyncWorker_0) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:29:42 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:30:03 WARNING (SyncWorker_13) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:30:13 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:30:34 WARNING (SyncWorker_6) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:30:44 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:37:16 WARNING (SyncWorker_5) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:37:26 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:37:26 WARNING (SyncWorker_5) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:42:25 WARNING (SyncWorker_19) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:42:35 WARNING (MainThread) [homeassistant.helpers.entity] Update of switch.side_yard_sprinklers is taking over 10 seconds
2020-04-02 21:42:35 WARNING (SyncWorker_19) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:50:10 WARNING (SyncWorker_5) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:50:20 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds
2020-04-02 21:50:20 WARNING (SyncWorker_5) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:53:47 WARNING (SyncWorker_10) [pyrainbird] Response: 503, Service Unavailable
2020-04-02 21:53:57 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.raindelay is taking over 10 seconds

Additional information

Not sure if this is helpful... I do not have a physical rain delay sensor, but the logs do mention one. Also, I have one unused zone named switch.unused_sprinkler_zone.

Answer 1 · 2020-04-04T07:38:12.000Z

Hey there @konikvranik, mind taking a look at this issue as its been labeled with a integration (rainbird) you are listed as a codeowner for? Thanks!

Answer 2 · 2020-04-08T13:22:17.000Z

@konikvranik , any thoughts on this? One thing I noticed that I was incorrect about was that these are all warnings; not errors. But regardless, my log is littered with them to the point where it is difficult to find any "real" errors.

Answer 3 · 2020-04-13T16:53:31.000Z

I have the same ... lots of warnings:

2020-04-13 18:45:32 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.rainsensor is taking over 10 seconds
2020-04-13 18:45:53 WARNING (SyncWorker_6) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:46:03 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.rainsensor is taking over 10 seconds
2020-04-13 18:46:55 WARNING (SyncWorker_1) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:47:05 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.rainsensor is taking over 10 seconds
2020-04-13 18:47:26 WARNING (SyncWorker_4) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:48:28 WARNING (SyncWorker_1) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:48:38 WARNING (MainThread) [homeassistant.helpers.entity] Update of binary_sensor.rainsensor is taking over 10 seconds
2020-04-13 18:48:59 WARNING (SyncWorker_9) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:49:09 WARNING (MainThread) [homeassistant.helpers.entity] Update of binary_sensor.rainsensor is taking over 10 seconds
2020-04-13 18:49:29 WARNING (SyncWorker_1) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:49:39 WARNING (MainThread) [homeassistant.helpers.entity] Update of binary_sensor.raindelay is taking over 10 seconds
2020-04-13 18:50:00 WARNING (SyncWorker_6) [pyrainbird] Response: 503, Service Unavailable
2020-04-13 18:50:10 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.rainsensor is taking over 10 seconds

RainBird model ESP-RZXe with rain sensor installed.

sensors in HA looks like this:

of course switches works ok so communication is not an issue.

Answer 4 · 2020-04-13T17:02:23.000Z

@ciechompl Glad to hear I'm not alone here! If these warnings are benign, maybe @konikvranik can include an option to suppress them from the log?

Answer 5 · 2020-04-13T17:06:08.000Z

I would rather see corrections into the code :) not hiding messages from the log :)
Especially that "[pyrainbird] Response: 503, Service Unavailable" does not sound like benign warning :(

Answer 6 · 2020-04-13T17:14:53.000Z

I agree. I was just trying to provide an option for those who enjoy bloated logs with hundreds of warnings a day. :)

Answer 7 · 2020-04-20T16:29:56.000Z

@konikvranik We have not heard from you. Is there someone else we should tag who might be available to address this issue?

Answer 8 · 2020-04-23T15:51:19.000Z

I am also getting this error/warning.

Answer 9 · 2020-04-23T16:05:03.000Z

I am also getting this error/warning.

@papacrown Thanks for chiming in. I'm glad to hear this issue is not isolated to only me. Unfortunately, the developer has not responded. I wonder if there is another way to get more traction on issues?

Answer 10 · 2020-04-23T16:08:46.000Z

Im going to try modifying https://github.com/konikvranik/pyrainbird to set logging to error instead of debug and copying it to my hassio instance, although I have no clue if that will work. Will let you know. I have seen the code author has been active in other issues, hope he responds soon.

…

On Apr 23, 2020, 11:05 AM -0500, mikesalz ***@***.***>, wrote: > I am also getting this error/warning. @papacrown Thanks for chiming in. I'm glad to hear this issue is not isolated to only me. Unfortunately, the developer has not responded. I wonder if there is another way to get more traction on issues? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

Answer 11 · 2020-04-29T03:58:45.000Z

I am also getting this error/warning.

@papacrown Thanks for chiming in. I'm glad to hear this issue is not isolated to only me. Unfortunately, the developer has not responded. I wonder if there is another way to get more traction on issues?

So I totally failed at trying that, sorry, couldn't get it to work.

Answer 12 · 2020-05-02T08:12:48.000Z

Hello, it is the response from Rainbird controller. Seems it is very weak HW with just single thread.
But you can investigate why it is sometimes responding by 503.

Answer 13 · 2020-05-02T20:47:33.000Z

@konikvranik Thanks for responding! I'm not sure what "very weak HW" means? If you are referring to wi-fi signal, that is definitely not the case. I also don't know how to investigate the 503 response. Being that these are just warnings, is it possible to change the integration to just completely ignore them?

Answer 14 · 2020-05-02T22:50:44.000Z

It's not about WiFi, but about chip and firmware inside Rainbird. You can ignore those warnings if all is working well. In other case this could be clue to solve problems.

Answer 15 · 2020-05-04T21:04:22.000Z

@konikvranik Yes, I can ignore it. But I would really prefer if HA could ignore it. It makes it difficult to find "real" issues when the logs are cluttered with hundreds of these each day. Is there a way to get the integration/HA to completely ignore these warnings??

Answer 16 · 2020-05-05T08:34:30.000Z

@mikesalz Yes, you can configure logger: https://www.home-assistant.io/integrations/logger/

Answer 17 · 2020-05-13T01:32:45.000Z

@konikvranik Thank you for the suggestions! I wasn't aware of logger. It LOOKS great, however I am not having any luck with it. Below is my yaml. I thought this would limit logging only to error or above. But I'm still getting all of the Rain Bird warnings. Any suggestions?

logger:
  default: error
  logs:
    # log level for HA core
    homeassistant.core: error

Answer 18 · 2020-05-13T05:49:12.000Z

Try to set pyrainbird: error

Answer 19 · 2020-05-13T11:54:10.000Z

@konikvranik
Hmmm..
My config now looks like this:

logger:
  default: error
  logs:
    # log level for HA core
    homeassistant.core: error

    # log level for all python scripts
    homeassistant.components.python_script: error
    
    pyrainbird: error

But I am still receiving this in my log:

Setup of sensor platform rainbird is taking over 10 seconds.
7:49:45 AM – Sensor (WARNING)
Response: 503, Service Unavailable
7:49:35 AM – components/rainbird/sensor.py (WARNING)

Answer 20 · 2020-05-17T11:35:19.000Z

@konikvranik I am still getting bombarded with pyrainbird warnings. Any other ideas?

Answer 21 · 2020-05-25T17:06:41.000Z

Not a solution but as a quick workaround - I commented out lines 30-31 here to disable the sensors from loading and it got rid of the warnings for me. ~~Note that this change does not survive upgrades so whenever you upgrade HA you'll have to comment these out again.~~ See below: #33614 (comment)

https://github.com/home-assistant/core/blob/dev/homeassistant/components/rainbird/__init__.py#L31-L32

I'm running it manually installed so the file for me was at /srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/rainbird/__init__.py. I had intended on working on a more permanent solution and may still if I can find the time. Hope this helps!

Answer 22 · 2020-05-25T17:28:01.000Z

Couldn’t we copy this folder to custom_components and have it survive upgrades that way? And then just delete it from custom_components whenever it’s fixed?

…

On May 25, 2020, 12:06 PM -0500, Richard Sween ***@***.***>, wrote: Not a solution but as a quick workaround - I commented out lines 30-31 here to disable the sensors from loading and it got rid of the warnings for me. Note that this change does not survive upgrades so whenever you upgrade HA you'll have to comment these out again. https://github.com/home-assistant/core/blob/dev/homeassistant/components/rainbird/__init__.py#L31-L32 I'm running it manually installed so the file for me was at /srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/rainbird/__init__.py. I had intended on working on a more permanent solution and may still if I can find the time. Hope this helps! — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

Answer 23 · 2020-05-25T20:57:24.000Z

@papacrown Hi, thanks for the tip! Yes, I just tested that by copying the rainbird directory to custom_components and then removing the comments from the HA rainbird plugin. Restarted HA and everything worked as expected. Haven't tested a HA upgrade but it should be OK. The caveat being you won't get any rainbird plugin updates (I assume). So the workaround becomes (as of 0.110.2):

Copy your rainbird directory to custom_components (create the custom_components directory next to your configuration.yaml if you don't already have one). For me, the command was:
cp -r /srv/homeassistant/lib/python3.7/site-packages/homeassistant/components/rainbird ~/.homeassistant/custom_components/
Comment out the lines in your custom_components/rainbird/__init__.py as above, currently lines 31 & 32.
Restart HA and warnings should be gone!

Answer 24 · 2020-05-25T21:04:47.000Z

@sweenr Yup, that'll be the only thing, we will have to wait and see if the developer updates the component to fix this. If they do, we would have to delete the custom component to load the developers version, if the error persists we would need to follow these steps again and edit custom_components/rainbird/__init__.py again.

For future reference, I'm on Hassio 0.110.2, the instructions were as follows (thanks @sweenr , copied your text where applicable):

Access Hassio Host --> https://developers.home-assistant.io/docs/operating-system/debugging/#ssh-access-to-the-host then type login
Access the container bash --> https://developers.home-assistant.io/docs/operating-system/debugging/#accessing-the-container-bash
Copy your rainbird directory to custom_components (create the custom_components directory next to your configuration.yaml if you don't already have one). For me, the command was:
cp -r /usr/src/homeassistant/components/rainbird /config/custom_components/
Comment out the lines in your custom_components/rainbird/__init__.py as above, currently lines 31 & 32.
Restart HA and warnings should be gone!

Answer 25 · 2020-05-26T13:18:31.000Z

I have the same issue. Removing the lines above probably disable the rain sensors of rainbird in HA. I don't use them, but I'll have a look if I can discover why a 503 is returned.

Answer 26 · 2020-06-06T00:10:33.000Z

@konikvranik This seems to be an ongoing issue for many HA users. Does @peternijssen 's link above provide any info that might help you fix this?

Answer 27 · 2020-06-16T00:53:23.000Z

@konikvranik Is there someone else who we can/should ask to fix these issues?

Answer 28 · 2020-07-07T23:44:49.000Z

I am seeing this problem as well, along with some other more detailed error tracing (which I'm not sure is releated):

020-07-07 16:36:33 WARNING (SyncWorker_2) [pyrainbird] Response: 503, Service Unavailable


2020-07-07 16:36:33 ERROR (MainThread) [homeassistant.components.switch] rainbird: Error on device update!


Traceback (most recent call last):


  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 319, in _async_add_entity


    await entity.async_device_update(warning=False)


  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 466, in async_device_update


    self.update  # type: ignore


  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run


    result = self.fn(*self.args, **self.kwargs)


  File "/usr/src/homeassistant/homeassistant/components/rainbird/switch.py", line 107, in update


    self._state = self._rainbird.get_zone_state(self._zone)


  File "/usr/local/lib/python3.7/site-packages/pyrainbird/__init__.py", line 125, in get_zone_state


    return self.zones.active(zone)


  File "/usr/local/lib/python3.7/site-packages/pyrainbird/data.py", line 104, in active


    return self.states[number - 1]


IndexError: tuple index out of range

Answer 29 · 2020-10-12T03:08:04.000Z

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

Answer 30 · 2022-03-21T10:22:53.000Z

Sorry to bring this back to life, but i am having the exact same issue.
HA 2022.3.1 set up as described here.

It seems to be working ok but I am getting a flood of 503 messages.

Is there any way to resolve this?
Thank you

Answer 31 · 2022-03-21T11:11:40.000Z

That's common. It is because Rainbird controller sometimes responds with this message. My suspicion is that it is not capable handle multiple requests in one time, so when you occasionally hit it by multiple requests at the same time it responds this way.

Answer 32 · 2022-03-22T09:12:37.000Z

That's common. It is because Rainbird controller sometimes responds with this message. My suspicion is that it is not capable handle multiple requests in one time, so when you occasionally hit it by multiple requests at the same time it responds this way.

So the only solution here is to hide the logs? Either by editing the files or by changing the logger config?

Answer 33 · 2022-03-22T10:55:16.000Z

I don't know other solution. You don't need to worry about this messages.

The problem

Environment

Problem-relevant configuration.yaml

Traceback/Error logs

Additional information

Problem-relevant `configuration.yaml`