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

RainMachine throwing odd errors #23650

Closed
bachya opened this issue May 3, 2019 · 31 comments · Fixed by #24358
Closed

RainMachine throwing odd errors #23650

bachya opened this issue May 3, 2019 · 31 comments · Fixed by #24358

Comments

@bachya
Copy link
Contributor

bachya commented May 3, 2019

Home Assistant release with the issue:

0.92.2

Last working Home Assistant release (if known):

?

Operating environment (Hass.io/Docker/Windows/etc.):

Docker

Component/platform:

rainmachine

Description of problem:

Recently, my particular HASS has been throwing several odd RainMachine errors (None).

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

rainmachine:
  controllers:
    - ip_address: !secret rainmachine_host
      password: !secret rainmachine_password

Traceback (if applicable):

Example:

2019-05-03 04:31:12 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "60e32719b6cf_zone_6": Error requesting data from 192.168.1.100: None

Additional information:

Not sure if the issue likes with HASS or regenmaschine.

@daniwebCH
Copy link

daniwebCH commented May 10, 2019

I have similar problems with 0.93.0b0.
Attached you have screenshot and logs.
In addition looks like strange to have sensor.flow_sensor_clicks_2.

20190510_rainmachine_0 93 0b0
20190510_rainmachine_0.93.0b0.log

@daniwebCH
Copy link

I do not know if helps, but there the returned values from rainmachine using postman {{HOST}}/provision?access_token={{ACCESS_TOKEN}}.
Firmware version: 4.0.1115
API: 4.6.0

{"system": {"httpEnabled": true, "rainSensorSnoozeDuration": 0, "selfTest": false, "uiUnitsMetric": true, "programZonesShowInactive": false, "localValveCount": 16, "programSingleSchedule": false, "standaloneMode": false, "masterValveAfter": 5, "touchAdvanced": false, "useFlowSensor": true, "useSoftwareRainSensor": false, "defaultZoneWateringDuration": 300, "maxLEDBrightness": 40, "simulatorHistorySize": 0, "vibration": false, "useCorrectionForPast": true, "spk5LockBrightness": 10, "masterValveBefore": 5, "touchProgramToRun": null, "useRainSensor": false, "wizardHasRun": true, "waterLogHistorySize": 365, "netName": "RainMachine", "automaticUpdates": true, "flowSensorLeakClicks": 0, "softwareRainSensorMinQPF": 5, "useBonjourService": true, "hardwareVersion": 3, "touchLongPressTimeout": 3, "showRestrictionsOnLed": false, "parserDataSizeInDays": 6, "programListShowInactive": true, "parserHistorySize": 365, "flowSensorStartIndex": 17, "allowAlexaDiscovery": false, "maxZoneDuration": 86400, "minLEDBrightness": 0, "minWateringDurationThreshold": 0, "simulatorSkipRunSoonDynamic": 43200, "touchSleepTimeout": 10, "lastLeakDetected": null, "touchAuthAPSeconds": 60, "carryOverInRestriction": false, "useCommandLineArguments": false, "flowSensorClicksPerCubicMeter": 1000, "databasePath": "/rainmachine-app/DB/Default", "touchCyclePrograms": true, "dedicatedMasterValve": false, "flowSensorWateringClicks": 6, "zoneListShowInactive": true, "rainSensorRainStart": null, "zoneDuration": [300, 11, 23, 300, 300, 300, 300, 300, 300, 300, 300, 300, 300, 300, 300, 300], "spk5TouchSleepTimeoutNight": 0, "rainSensorIsNormallyClosed": true, "spk5LCDBrightness": 50, "useMasterValve": false, "runParsersBeforePrograms": true, "spk5LEDBrightness": 15, "maxWateringCoef": 2, "mixerHistorySize": 365}, "location": {"elevation": 430, "doyDownloaded": true, "zip": null, "windSensitivity": 0.5, "krs": 0.16, "stationID": 40095, "stationSource": "grid", "et0Average": 4.7960000000000003, "latitude": xxxxxxx, "state": "Default", "stationName": [190, 86], "wsDays": 2, "stationDownloaded": true, "address": "Default", "rainSensitivity": 0.80000000000000004, "timezone": xxxxxx, "longitude": xxxxxxxxx, "name": "Default"}}

@bachya
Copy link
Contributor Author

bachya commented May 11, 2019

@daniwebCH Thanks for the feedback. The issue with sensor.flow_sensor_clicks_2 will be addressed soon.

I have a good mapping of all of the APIs, but none of my tests have yielded this issue (a None exception). Do you happen to use any Unifi networking gear?

@daniwebCH
Copy link

daniwebCH commented May 11, 2019

Hi,
yes, I have the cloud key, switch and 2 access points. The test rpi3B+ is connected with the rj45 to the unifi switch.
But I did not install the Unifi Cloud Key on the hassio.

Daniele

@bachya
Copy link
Contributor Author

bachya commented May 12, 2019

Thanks for the update. Of the now three people (myself included) who have reported this issue, everyone is using Unifi gear...

@daniwebCH
Copy link

Thanks for the update. Of the now three people (myself included) who have reported this issue, everyone is using Unifi gear...

Any idea if this issue with Unifi is somewhere handled?
Is this a question of HS or a configuration of the Unifi network?

@bachya
Copy link
Contributor Author

bachya commented May 15, 2019

@daniwebCH
Copy link

daniwebCH commented May 15, 2019

This might be a possibility: https://support.rainmachine.com/hc/en-us/community/posts/115007448168-HD-12-Keeps-disconnecting-from-wi-fi

I would not point to disconnect/connect to wifi, this I would see on the events on Unifi for this device and when I navigate to the web interface of the rainmachine I would notice it.

The fact is that I really NEVER got the flowSensor values.

PS: In addition I try to get those info via postman and I always get an answer..... I'm not so sure at the end that it is really an issue of Unifi.. but more HA

@bachya
Copy link
Contributor Author

bachya commented May 15, 2019

The fact is that I really NEVER got the flowSensor values.

You wouldn't – that functionality is going out in 0.93.0, which hasn't been released yet: #23221

PS: In addition I try to get those info via postman and I always get an answer..... I'm not so sure at the end that it is really an issue of Unifi.. but more HA

Trying things in Postman is not a valid test methodology in this case; it doesn't adequately mimic the actual functionality of the integration. For instance, manually firing tests in Postman:

  • doesn't fire requests every 60 seconds (like the integration does)
  • doesn't fire multiple requests in parallel (like the integration does)

This same functionality works fine in several other integrations; until I see otherwise, I'm inclined to believe that the issue lies in some combination of RainMachine and Unifi gear.

@daniwebCH
Copy link

daniwebCH commented May 16, 2019

You wouldn't – that functionality is going out in 0.93.0, which hasn't been released yet: #23221

In one test rpi3B+ I'm running 0.93.0b4, there I see the sensors but not the values, as I reported few post before, I supposed that it should be operational on this version...

Trying things in Postman is not a valid test methodology in this case; it doesn't adequately mimic the
actual functionality of the integration. For instance, manually firing tests in Postman:

I completely agree for random missing data, but it would be strange that the provision info is the only one missing, and always missing... (unless the position on the request sequence is the issue)

Added:
I just tried with 0.93.0 and same issue and no provision data, see log.
From log I see every 1 minute request(s).
I assume that not every time all the data are requested, as the majority of times there are no issues reported but I never get the provision data.
Is there maybe something different when those requests are sent?
home-assistant.log

Added2:
Now I have this maybe interesting....
2019-05-16 13:36:03 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport Traceback (most recent call last): File "uvloop/sslproto.pyx", line 574, in uvloop.loop.SSLProtocol._do_shutdown File "/usr/local/lib/python3.7/ssl.py", line 767, in unwrap return self._sslobj.shutdown()

See the full log, I have the impression that the issues are more often coming:

home-assistant.log.txt

@daniwebCH
Copy link

I tried to remove the rainmachine from integration and tried to specify it on configuration.yaml as described in the component description.

This makes rainmachine discoverable but I still have to insert the credentials and port from the gui.
From the GUI no way to set port 8081 and no ssl.

It would be nice to have no ssl in order to easier follow what is going on with wireshark...
any idea?

@bachya
Copy link
Contributor Author

bachya commented May 16, 2019

I completely agree for random missing data, but it would be strange that the provision info is the only one missing, and always missing... (unless the position on the request sequence is the issue)

Added:
I just tried with 0.93.0 and same issue and no provision data, see log.
From log I see every 1 minute request(s).
I assume that not every time all the data are requested, as the majority of times there are no issues reported but I never get the provision data.
Is there maybe something different when those requests are sent?

This is not what I'm experiencing: the None exception seems to occur randomly with any RainMachine API call (not just with provision calls). Consider my log from this morning:

2019-05-16 07:42:57 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for program "abcdef1234567890_program_2": Error requesting data from REDACTED HOSTNAME: None
2019-05-16 08:02:07 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.universal: Error requesting data from REDACTED HOSTNAME: None
2019-05-16 08:03:08 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.universal: Error requesting data from REDACTED HOSTNAME: None
2019-05-16 08:20:29 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for program "abcdef1234567890_program_1": Error requesting data from REDACTED HOSTNAME: None
2019-05-16 08:21:30 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "abcdef1234567890_zone_5": Error requesting data from REDACTED HOSTNAME: None
2019-05-16 08:22:31 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for program "abcdef1234567890_program_2": Error requesting data from REDACTED HOSTNAME: None
2019-05-16 09:21:15 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.current: Error requesting data from REDACTED HOSTNAME: None

So, we have:

  • 3 errors while updating programs
  • 1 error while updating zones
  • 2 errors while updating universal restrictions
  • 1 error while updating current restrictions

...all at random times and without any observable pattern. At no point did I fail to get provision data.

Added2:
Now I have this maybe interesting....
2019-05-16 13:36:03 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport Traceback (most recent call last): File "uvloop/sslproto.pyx", line 574, in uvloop.loop.SSLProtocol._do_shutdown File "/usr/local/lib/python3.7/ssl.py", line 767, in unwrap return self._sslobj.shutdown()

uvloop is used throughout Home Assistant; unfortunately, these don't directly trace to anything RainMachine-related.

See the full log, I have the impression that the issues are more often coming:

home-assistant.log.txt

In reviewing your log, I'm seeing the issue I've reported here, but just FYI, I'm also seeing several other issues unrelated to the component. For instance, lines 718-721:

2019-05-16 13:39:00 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "d46e0e0c18a4_zone_2": Timeout during request: zone/2
2019-05-16 13:39:00 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "d46e0e0c18a4_zone_5": Timeout during request: zone/5
2019-05-16 13:39:00 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "d46e0e0c18a4_zone_4": Timeout during request: zone/4
2019-05-16 13:39:00 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "d46e0e0c18a4_zone_6": Timeout during request: zone/6

...show that your Home Assistant host is timing out while attempting to communicate with your RainMachine (indicative of a network issue).

Elsewhere, lines 740-742:

2019-05-16 13:39:12 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating provision.settings: Error requesting data from 192.168.18.70: Cannot connect to host 192.168.18.70:8080 ssl:True [Host is unreachable]
2019-05-16 13:39:12 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.current: Error requesting data from 192.168.18.70: Cannot connect to host 192.168.18.70:8080 ssl:True [Host is unreachable]
2019-05-16 13:39:12 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.universal: Error requesting data from 192.168.18.70: Cannot connect to host 192.168.18.70:8080 ssl:True [Host is unreachable]

...show that your Home Assistant host could not reach your RainMachine over the local network.

Again, just an FYI so that as you review logs, you don't combine multiple issues with the key one described here.

I tried to remove the rainmachine from integration and tried to specify it on configuration.yaml as described in the component description.

This makes rainmachine discoverable but I still have to insert the credentials and port from the gui.
From the GUI no way to set port 8081 and no ssl.

There is a way to set the port in the GUI:

Screen Shot 2019-05-16 at 11 48 56 AM

You are correct that there is currently no way to "disable" SSL from the GUI; I haven't found a compelling need for this.

It would be nice to have no ssl in order to easier follow what is going on with wireshark...
any idea?

You're wanting to disable SSL on the RainMachine itself? Can Wireshark not implement an SSL proxy like Fiddler, Charles, etc. can?

@daniwebCH
Copy link

Let's try to concentrate on main topics ;-)

1-PROVISION DATA
If looks like random, why I never get the info regarding flow from provision data?

2-NETWORK
Any idea of what I could try diagnose/solve it?
I enabled the unifi hystorical data for the rainmachine, what I see as potentially strange are the rx retries.
20190517_rainmachine_unifi_stat

3-CONFIGURATION

You're wanting to disable SSL on the RainMachine itself? Can Wireshark not implement an SSL proxy like Fiddler, Charles, etc. can?

As far as I understood the rainmachine:

  • on port 8080 expects ssl
  • on port 8081 expects no ssl

On the GUI selecting the port 8081 is not making communication without ssl.
On this case if only the GUI config has to be used, the component documentation shall be updated (as it has no effect)

@daniwebCH
Copy link

1-PROVISION DATA (update1)
I enabled the wifi from the internet provider box, after very short test during 4 minutes no issues reported by rainmachine, see log below.
BUT still no provision data
20190517_rainmachine_flowSensor

`
2019-05-17 16:10:17 DEBUG (MainThread) [homeassistant.components.rainmachine] Updating RainMachine sensor data

2019-05-17 16:11:18 DEBUG (MainThread) [homeassistant.components.rainmachine] Updating RainMachine sensor data

2019-05-17 16:12:19 DEBUG (MainThread) [homeassistant.components.rainmachine] Updating RainMachine sensor data

2019-05-17 16:13:20 DEBUG (MainThread) [homeassistant.components.rainmachine] Updating RainMachine sensor data`

@bachya
Copy link
Contributor Author

bachya commented May 17, 2019

Do you know whether the API from your local RainMachine is returning flow sensor data? You can test via the underlying library:

  1. Clone regenmaschine:

$ git clone https://github.com/bachya/regenmaschine.git

  1. Initialize the dev environment:

$ make init

  1. Edit example.py and include your pertinent connection info.
  2. Run example.py:

$ pipenv run python3 example.py

Does the output show flow sensor data anywhere?

@daniwebCH
Copy link

Do you know whether the API from your local RainMachine is returning flow sensor data?

The rainmachine is providing the data see one of my first posts.
If you mean with your library, which environment you suggest to use?
Yesterday I tried your repository lib on raspberry but I failed, I took python and recompiled but after I had issues with pip....

@daniwebCH
Copy link

daniwebCH commented May 20, 2019

I created a virtual machine, installed pip, environment....
On your example yes I get the provision info you request to test.
The sensor data missig on HA are not present, to see them you have to extract similar as databasePath.
I added the lines to printf 'flowSensorWateringClicks' similar to 'databasePath' and I get the info of the clicks.

Added: Maybe on code not taken in account that those params are "below" the 'system'

@bachya
Copy link
Contributor Author

bachya commented May 20, 2019

Paste your data here so I can see an example; I don't have a flow sensor, so I can't test directly.

@daniwebCH
Copy link

daniwebCH commented May 20, 2019

I will make it tomorrow, but you can enable the flow sensor feature even if you do not have one (the only value you will not see moving are the clicks)

Added:
There you have the example modified by me (I commented out actions as I do not want to start watering).
You can see the printf I added as they have the comment dwy_added (I added .txt to the .py as I can not upload as it is named)

dwy_example.py.txt

dwy_OutLog.txt

@LeapFrogSupport
Copy link

LeapFrogSupport commented May 26, 2019

Home Assistant release with the issue: 0.93.2
Last working Home Assistant release (if known): Unknown
Operating environment (Hass.io/Docker/Windows/etc.): Rpi3B+/Raspbian/Docker
Component/platform: rainmachine
Description of problem: I'm also seeing occasional "None" errors as well as Timeouts - they've been around at least since 0.87.0. Functionality doesn't seem to be affected but the errors do clog up the log. Here's another configuration / set of data points if they are of help to you.

Problem-relevant configuration.yaml entries:

rainmachine:
  controllers:
    - ip_address: 192.168.1.157
      password: *******
      port: 8081
      ssl: false

Traceback (if applicable): See home-assistant.log, attached.
home-assistant.log

Additional information:
WiFi/LAN connectivity:
RainMachine Mini-8 Hardware V2 via WiFi to:
TP-Link AV500 2-Port Powerline Gigabit Wi-Fi Adapter Kit, 2-Kit (TL-WPA4220 KIT) upstream to:
TrendNet TEG-S5G Gigabit Switch to Rpi

Rainmachine log attached, no errors indicated (I also checked in DEBUG mode, still no errors shown on the Rainmachine log)
rain_machine.log

05/26/19 Edit: Add information re: WiFi connectivity
I ping'd the Mini-8 for about an hour from the Rpi and while the RTT was < 10ms most of the time occasionally it would be much longer or would fail altogether. So I moved the (TP-Link Powerline) WiFi access point closer to the Mini-8, it is now just a few feet away and rock solid, no lost packets over a 1 hour time frame. As a result this seems to have cleared the "Timeout" and "Fatal error on transport" errors, but the "Error requesting data from 192.168.1.157: None" log entries still continue (see below).

2019-05-26 15:56:49 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "a8803824ead0_zone_6": Error requesting data from 192.168.1.157: None
2019-05-26 16:12:58 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating provision.settings: Error requesting data from 192.168.1.157: None
2019-05-26 16:12:58 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.universal: Error requesting data from 192.168.1.157: None
2019-05-26 16:13:59 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating provision.settings: Error requesting data from 192.168.1.157: None
2019-05-26 16:13:59 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.current: Error requesting data from 192.168.1.157: None
2019-05-26 16:44:24 ERROR (MainThread) [homeassistant.components.rainmachine] There was an error while updating restrictions.universal: Error requesting data from 192.168.1.157: None
2019-05-26 17:00:45 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "a8803824ead0_zone_8": Error requesting data from 192.168.1.157: None

05/30/19 Edit: Add HA log and Wireshark Packet Capture file.
For the 30 minutes from 08:00 to 08:30 on 5/30 here's the HA log along with a Wireshark capture log for all traffic in/out of the two nodes - the Rpi3B+ is 192.168.1.163
homeassistant_0800-0830.log
wireshark_0800-0830.pcapng.gz

@bachya
Copy link
Contributor Author

bachya commented Jun 6, 2019

Thanks, @LeapFrogSupport – from your info, it looks like we can rule out this being a UniFi issue. I'll keep digging.

@LeapFrogSupport
Copy link

Thanks for following up -

Please let me know if there is anything else I can do to help debug this. (The RM component errors are the sole remaining extraneous entries in the HA logfile!).

@bachya
Copy link
Contributor Author

bachya commented Jun 6, 2019

Finally had a breakthrough. That None exception message is coming from an aiohttp.client_exceptions.ServerDisconnectedError exception. According to aiohttp's author, this exception is raised when the "server" (in this case, the RainMachine) closes a long-running HTTP socket connection (and it's up to the implementer to handle).

One suggestion is to set the Connection header is set to close – this will ensure that the connection will be closed after every request (which might sacrifice some speed, but it shouldn't be noticeable). Testing now.

@bachya
Copy link
Contributor Author

bachya commented Jun 6, 2019

I think we have a winner: 2 hours and zero issues (whereas a "normal" 2 hours would have seen 10+ on my system). Will submit a PR shortly.

@LeapFrogSupport
Copy link

Outstanding - can I put a copy in /config/custom_components or is testing more complicated than that?

@bachya
Copy link
Contributor Author

bachya commented Jun 6, 2019

Exactly; you'll be able to follow the process here: https://developers.home-assistant.io/blog/2019/04/12/new-integration-structure.html

@LeapFrogSupport
Copy link

Roger that.

@LeapFrogSupport
Copy link

LeapFrogSupport commented Jun 6, 2019

Probably a newbie error, but I downloaded and extracted regenmaschine-dev (perfekter name BTW) from Github, put a downloaded copy of the contents of the regenmaschine folder in custom_components/regenmaschine along with an empty __init__.py file, restarted HA and within a few minutes got this:

"2019-06-06 17:22:42 ERROR (MainThread) [homeassistant.components.rainmachine.switch] Unable to update info for zone "a8803824ead0_zone_1": Error requesting data from 192.168.1.157: None"

Maybe I was too quick on the download, but if not and if you'll tell me what I did wrong I'll fix it and retest. Thanks.

@bachya
Copy link
Contributor Author

bachya commented Jun 6, 2019

@LeapFrogSupport Not quite: you'll want to put a copy of the HASS integration, not the underlying library, into custom_components. The only change you'll need to make is to replace manifiest.json with the version from my PR (#24358).

@LeapFrogSupport
Copy link

LeapFrogSupport commented Jun 6, 2019

OK, sorry for the delay but I had to find my way around Github, it has been awhile. I do like the new Github Windoze client though, beats the heck out of git-svn.

So I installed a copy of the integration in config/custom_components/rainmachine and copied over the new manifest.json and we're up and running and unfortunately...

2019-06-06 18:14:51 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for rainmachine which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2019-06-06 18:19:39 ERROR (MainThread) [custom_components.rainmachine.switch] Unable to update info for zone "a8803824ead0_zone_8": Error requesting data from 192.168.1.157: None

Another newbie error perhaps? In any case I'm off to dinner and will pick this up again in the morning. Thanks for all your help and for doing such a great job on the rainmachine component.

06/07/19 Edit: Morning update - I was still seeing the "None" errors this morning. I verified that the updated dependency/library regenmaschine 1.5.1 was correctly downloaded to the config/deps/lib/python3.7/site-packages/regenmaschine directory. And then it occurred to me that the dependency must be downloaded upon the initial restart of HA, so maybe it takes a second restart for HA to pick up the custom code. Sure enough, I did a restart this morning and after a couple of hours, no error messages.

Once again, thanks for digging deep and solving this one.

@bachya
Copy link
Contributor Author

bachya commented Jun 6, 2019

@LeapFrogSupport Not sure what's going on there. Since the change was just merged, you could also install a test instance of HASS somewhere, configure only this component, and test that way.

Thanks for your kind words!

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

Successfully merging a pull request may close this issue.

4 participants