[Hydrawise] Binding stops polling after error / exception

[NicGray78]

Openhab : 3.1.0 Hydrawaise Binding : 3.1.0.202106121717

I've noticed a few times where the binding seems to stop updating after a few days and stale data is left displayed on my sitemaps.

I ran the binding in debug and caught the exception, which seems to be related to the account (possibly bad password / not available) and whilst this update might be dropped, the binding should re-attempt a minute later, then a minute after that, etc:

2022-06-20 19:22:23.638 [TRACE] [l.api.graphql.HydrawiseGraphQLClient] - Received Response: {"data":{"me":{"email":"xxxxxx@gmail.com","lastContact":"Sat, 21 May 22 04:17:32 +0000","controllers":[{"id":xxxxxxxx,"name":"My Controller","status":{"summary":"All
 good!","online":true,"lastContact":{"timestamp":1655669237}},"location":{"coordinates":{"latitude":-33.7697072,"longitude":151.2819771},"forecast":[{"time":"Mon, 20 Jun 22 00:00:00 +1000","updateTime":"Mon, 20 Jun 22 05:14:27 +1000","conditions":"Scattered Show
ers","averageWindSpeed":{"value":12,"unit":"km\/h"},"highTemperature":{"value":18,"unit":"\u00b0C"},"lowTemperature":{"value":9,"unit":"\u00b0C"},"probabilityOfPrecipitation":45.44,"precipitation":{"value":0.03,"unit":"mm"},"averageHumidity":69},{"time":"Tue, 21
 Jun 22 00:00:00 +1000","updateTime":"Mon, 20 Jun 22 05:14:27 +1000","conditions":"Light Rain","averageWindSpeed":{"value":16,"unit":"km\/h"},"highTemperature":{"value":20,"unit":"\u00b0C"},"lowTemperature":{"value":10,"unit":"\u00b0C"},"probabilityOfPrecipitation":77.2,"precipitation":{"value":0.92,"unit":"mm"},"averageHumidity":64},{"time":"Wed, 22 Jun 22 00:00:00 +1000","updateTime":"Mon, 20 Jun 22 05:14:27 +1000","conditions":"Sunny","averageWindSpeed":{"value":20,"unit":"km\/h"},"highTemperature":{"value":18,"unit":"\u00b0C"},"lowTemperature":{"value":8,"unit":"\u00b0C"},"probabilityOfPrecipitation":19.04,"precipitation":{"value":0,"unit":"mm"},"averageHumidity":55}]},"zones":[{"id":4473267,"name":"Bamboo","status":{"suspendedUntil":null},"icon":{"id":1,"fileName":"leaf.png","customImage":null},"number":{"value":1,"label":"Zone 1"},"scheduledRuns":{"summary":"Bamboo will next run on Tuesday, 21st of June 2022, 07:00AM (Sydney Time) for 20 minutes. Normal watering cycle","currentRun":null,"nextRun":{"id":"21412093300","startTime":{"timestamp":1655758800},"endTime":{"timestamp":1655760000},"duration":20}}},{"id":4469122,"name":"Trees and Shrubs","status":{"suspendedUntil":null},"icon":{"id":4,"fileName":"flower.png","customImage":null},"number":{"value":3,"label":"Zone 3"},"scheduledRuns":{"summary":"Trees and Shrubs will next run on Wednesday, 22nd of June 2022, 07:00AM (Sydney Time) for 15 minutes. Normal watering cycle","currentRun":null,"nextRun":{"id":"21412093301","startTime":{"timestamp":1655845200},"endTime":{"timestamp":1655846100},"duration":15}}},{"id":4472303,"name":"Grass Pool","status":{"suspendedUntil":null},"icon":{"id":10,"fileName":"grass.png","customImage":null},"number":{"value":4,"label":"Zone 4"},"scheduledRuns":{"summary":"Grass Pool will next run on Wednesday, 22nd of June 2022, 07:15AM (Sydney Time) for 20 minutes. Normal watering cycle","currentRun":null,"nextRun":{"id":"21412093302","startTime":{"timestamp":1655846100},"endTime":{"timestamp":1655847300},"duration":20}}},{"id":4472467,"name":"Grass Beds","status":{"suspendedUntil":null},"icon":{"id":10,"fileName":"grass.png","customImage":null},"number":{"value":5,"label":"Zone 5"},"scheduledRuns":{"summary":"Grass Beds will next run on Wednesday, 22nd of June 2022, 07:35AM (Sydney Time) for 20 minutes. Normal watering cycle","currentRun":null,"nextRun":{"id":"21412093303","startTime":{"timestamp":1655847300},"endTime":{"timestamp":1655848500},"duration":20}}}],"sensors":[]}]}}}
2022-06-20 19:22:23.639 [TRACE] [l.handler.HydrawiseControllerHandler] - onData my controller id xxxxxxxxx
2022-06-20 19:22:23.639 [TRACE] [l.handler.HydrawiseControllerHandler] - Updating Controller xxxxxxxx sensors [] forecast [org.openhab.binding.hydrawise.internal.api.graphql.schema.Forecast@7092d538, org.openhab.binding.hydrawise.internal.api.graphql.schema.Forecast@4caed024, org.openhab.binding.hydrawise.internal.api.graphql.schema.Forecast@4caa9a02] 
2022-06-20 19:22:23.640 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast1 temperaturehigh ?C 18
2022-06-20 19:22:23.640 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast1 temperaturelow ?C 9
2022-06-20 19:22:23.640 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast2 temperaturehigh ?C 20
2022-06-20 19:22:23.640 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast2 temperaturelow ?C 10
2022-06-20 19:22:23.640 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast3 temperaturehigh ?C 18
2022-06-20 19:22:23.640 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast3 temperaturelow ?C 8
2022-06-20 19:22:23.640 [TRACE] [l.handler.HydrawiseControllerHandler] - Updateing Zone zone1 Bamboo 
2022-06-20 19:22:23.640 [TRACE] [l.handler.HydrawiseControllerHandler] - Updateing Zone zone2 Trees and Shrubs 
2022-06-20 19:22:23.640 [TRACE] [l.handler.HydrawiseControllerHandler] - Updateing Zone zone3 Grass Pool 
2022-06-20 19:22:23.640 [TRACE] [l.handler.HydrawiseControllerHandler] - Updateing Zone zone4 Grass Beds 
2022-06-20 19:23:23.641 [TRACE] [l.api.graphql.HydrawiseGraphQLClient] - Sending Request: {"query":"{\n  me {\n    email\n    lastContact\n      controllers {\n      id\n      name\n        status {\n        summary\n        online\n        lastContact {\n          timestamp\n        }\n      }    \n      location {\n        coordinates {\n          latitude\n          longitude\n        }\n        forecast(days: 3) {\n          time\n          updateTime\n          conditions\n          averageWindSpeed {\n            value\n            unit\n          }\n          highTemperature {\n            value\n            unit\n          }\n          lowTemperature {\n            value\n            unit\n          }\n          probabilityOfPrecipitation\n          precipitation {\n            value\n            unit\n          }\n          averageHumidity\n        }\n      }\n      zones {\n        id\n        name\n        status {\n          suspendedUntil {\n            timestamp\n          }     \n        }\n        icon {\n          id\n          fileName\n          customImage {\n            id\n            url\n          }\n        }\n        number {\n          value\n          label\n        }\n        scheduledRuns {\n          summary\n          currentRun{\n             id\n            startTime {\n              timestamp\n            }\n            endTime {\n              timestamp\n            }\n            duration\n            status {\n              value\n              label\n            }\n          }\n          nextRun {\n            id\n            startTime {\n              timestamp\n            }\n            endTime {\n              timestamp\n            }\n            duration\n          }\n        }\n      }\n      sensors {\n        id\n        name\n        input {\n          number\n          label\n        }\n        status {\n          active\n          waterFlow {\n            value\n            unit\n          }\n        }\n        model {\n          modeType\n          active\n          offLevel\n          offTimer\n          delay\n        }\n      }\n    }\n  }\n}"}
**2022-06-20 19:23:24.364 [TRACE] [l.api.graphql.HydrawiseGraphQLClient] - Received Response: 
2022-06-20 19:23:24.364 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
        at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:192) ~[?:?]
        at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:183) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:834) [?:?]**
2022-06-20 19:30:00.928 [INFO ] [enhab.core.model.script.garage.rules] - Garage Door is Closed
2022-06-20 19:45:00.564 [INFO ] [enhab.core.model.script.lights.rules] - Bedtime, some lights off, some low

[jp-Ll]

openHAB 3.3 Hydrawise Binding : 3.3.0

I have the same problem: After running smootly for 1 day, the binding stops updating the items (zones and weather). After Disabling and immediately Enabling the "Hydrawise Account Thing" in "Things Settings" the binding works smootly again.

Thank you very much in advance !

[digitaldan]

@jp-Ll can you post the error in your log file please to confirm its the same issue?

@NicGray78 i'm having trouble seeing how an NPE was thrown at line 192, that should not be possible, which is super odd b/c obviously it is happening, so this may take bit to debug. I can also see that the Hydrawise API returns an empty string on the failed call, which should throw an exception we catch, but that also does not seem to be happening.

[NicGray78]

Do you want me to run a packet capture?

[digitaldan]

Do you want me to run a packet capture?

No, the logs show the returning result, so i just need to debug that a little more.

[jp-Ll]

Sorry for the late reply, it took me some time to catch a relevant error message. Is this of any help for you? Kind regards, Joachim

2022-07-21 18:11:19.520 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast2 temperaturelow °C 16

2022-07-21 18:11:19.526 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast3 temperaturehigh °C 26

2022-07-21 18:11:19.529 [DEBUG] [l.handler.HydrawiseControllerHandler] - TEMP forecast3 temperaturelow °C 15

2022-07-21 18:29:55.722 [DEBUG] [rnal.handler.HydrawiseAccountHandler] - Retrying failed poll

org.openhab.binding.hydrawise.internal.api.HydrawiseConnectionException: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1066aff::DecryptedEndPoint@df1913{l=/192.168.178.xxx:34194,r=app.hydrawise.com/44.236.19.36:443,OPEN,fill=-,flush=-,to=1116380/0}

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLRequest(HydrawiseGraphQLClient.java:318) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLQuery(HydrawiseGraphQLClient.java:256) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.queryControllers(HydrawiseGraphQLClient.java:117) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:188) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:183) ~[?:?]

Caused by: java.util.concurrent.ExecutionException: java.io.EOFException: HttpConnectionOverHTTP@1066aff::DecryptedEndPoint@df1913{l=/192.168.178.xxx:34194,r=app.hydrawise.com/44.236.19.36:443,OPEN,fill=-,flush=-,to=1116380/0}

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLRequest(HydrawiseGraphQLClient.java:301) ~[?:?]

Caused by: java.io.EOFException: HttpConnectionOverHTTP@1066aff::DecryptedEndPoint@df1913{l=/192.168.178.xxx:34194,r=app.hydrawise.com/44.236.19.36:443,OPEN,fill=-,flush=-,to=1116380/0}

2022-07-21 18:30:41.217 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hydrawise:account:f4b9xxxf80' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): java.io.IOException: Exception in oauth communication, grant type refresh_token

2022-07-21 18:30:41.224 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hydrawise:controller:f4b9xxxf80:83xxx9' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2022-07-21 18:30:41.174 [DEBUG] [l.api.graphql.HydrawiseGraphQLClient] - Could not send request

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLRequest(HydrawiseGraphQLClient.java:285) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLQuery(HydrawiseGraphQLClient.java:256) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.queryControllers(HydrawiseGraphQLClient.java:117) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:188) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:206) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:183) ~[?:?]

2022-07-21 18:30:41.201 [DEBUG] [rnal.handler.HydrawiseAccountHandler] - Will try again during next poll period

org.openhab.binding.hydrawise.internal.api.HydrawiseConnectionException: java.io.IOException: Exception in oauth communication, grant type refresh_token

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLRequest(HydrawiseGraphQLClient.java:307) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLQuery(HydrawiseGraphQLClient.java:256) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.queryControllers(HydrawiseGraphQLClient.java:117) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:188) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:206) ~[?:?]

    at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:183) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLRequest(HydrawiseGraphQLClient.java:285) ~[?:?]

    at org.openhab.binding.hydrawise.internal.api.graphql.HydrawiseGraphQLClient.sendGraphQLRequest(HydrawiseGraphQLClient.java:285) ~[?:?]

[digitaldan]

That looks like a networking issue on your box, not binding specific. Does the binding recover on its own after some amount of time ? Since it then also fails trying to refresh the auth token, i'm guessing it may not. in any case, I don't think it's related to this issue.

[BillGOH]

Maybe I have the same issue. I saw that the Hydrawise binding showed old values (for next run time, rain sensor). I did disable and enable the account thing and I got the correct values. I did not see any error, however (which does not mean there migth have been one).

My system: openHAB 3.3 with openHABian

[NicGray78]

Hmm the exception appears to only show at DEBUG level which might be why I get it (I'm in DEBUG) and you didn't.... @digitaldan should it not be logged as ERROR / WARN / FATAL?

[digitaldan]

@digitaldan should it not be logged as ERROR / WARN / FATAL?

No, the exception mentioned above is caught and the status is reported back to the thing as seen in this line: OFFLINE (COMMUNICATION_ERROR): java.io.IOException: Exception in oauth communication, grant type refresh_token

Binding developers are discouraged from printing these types of error to the logs at INFO/WARN, especially b/c we will try and poll again as seen in the log above (Will try again during next poll period) . Now if its not reconnecting, or gets stuck in a loop not connecting, then thats a bug that needs to be fixed.

The error in your case was not caught in the code, and was thrown outside the binding which uses the system level debug level, in this case WARN.

[digitaldan]

@NicGray78 I noticed you said the binding version is 3.1.0.202106121717 which is odd, as thats from 2021/06/12 and this binding was switched to use GraphQL on August 1st of 2021. Are you running a beta version i may have posted when i was developing the GraphQL rewrite ?

[NicGray78]

I think I got it from that link where you mentioned that the pre-release was out, but I copied it in Jan 2022 -> org.openhab.binding.hydrawise-3.1.0-SNAPSHOT.jar

I see there is now a 3.4 version.. can try that but will it work against a 3.1 build? If not then I just need to mentally prepare for a system upgrade as I think there are some zwave changes that cause some headaches.

[BillGOH]

Today same problem: Rain sensor and running time values are outdated. No error in log. What I did notice some time ago by the way: The "last contact time" channel does not seem to work.

[digitaldan]

@BillGOH can you run the binding with trace logging ? Also when the values are not updating can you check the status of the the Account thing, does it say 'Online' or something else? Also are only some values not updating ?

[digitaldan]

@NicGray78 I'm not sure if its compatible, but i run a large z-wave network and have not had any issues if you upgrade. You can try manually installing the 3.2 or 3.3 version from

https://openhab.jfrog.io/ui/native/libs-release/org/openhab/addons/bundles/org.openhab.binding.hydrawise/

if you want to test.

[BillGOH]

@digitaldan Thank you for your response and your efforts. I enabled TRACE-logging; however, I had already reenabled the account thing so I have to wait until next time when the problem occurs.

When the channels are not updating anymore, both account thing and controller thing are online. I have to disable and enable the account thing to get new values then.

What I can already see from the TRACE-log is the following: 2022-08-07 17:40:02.991 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:64193534a4:XXX:system#lastcontact 2022-08-07T07:56:35.000+0000 However, my item "last contact" always shows NULL.

[digitaldan]

However, my item "last contact" always shows NULL.

yeah, thats a bug in the binding, i had apparently called that channel lastcontacttime in some places and lastcontact in others, to make matters worse the docs call the channel lastContact with a capital C , not sure why that channel name was so hard to keep straight. I have fixed this in the binding to just be lastcontact and will push those changes up soon.

[NicGray78]

@NicGray78 I'm not sure if its compatible, but i run a large z-wave network and have not had any issues if you upgrade. You can try manually installing the 3.2 or 3.3 version from

https://openhab.jfrog.io/ui/native/libs-release/org/openhab/addons/bundles/org.openhab.binding.hydrawise/

if you want to test.

So All upgraded to 3.3 with no major issues (the zwave ones I referenced before was to do with strict checking of parameters that had been allowed to be out of acceptable range before)

Just a reminder that I don't have a Zone 2 (I logged a previous bug that you fixed regarding this)

Now the binding starts up, gets updates but then throws an exception..

2022-08-11 08:50:12.234 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#summary Grass Beds will next run on Sunday, 14th of August 2022, 07:55AM (Sydney Time) for 20 minutes. Normal watering cycle 2022-08-11 08:50:12.234 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#duration 20 min 2022-08-11 08:50:12.234 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#nextruntime 2022-08-13T21:55:00.000+0000 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#run OFF 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#timeleft 0 min 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#suspend OFF 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:zone5#suspenduntil UNDEF 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:allzones#run OFF 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:allzones#suspend OFF 2022-08-11 08:50:12.235 [DEBUG] [l.handler.HydrawiseControllerHandler] - updateState updating hydrawise:controller:myaccount:687834:allzones#suspenduntil UNDEF 2022-08-11 08:50:12.241 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: java.util.ConcurrentModificationException: null at java.util.ArrayList.forEach(ArrayList.java:1543) ~[?:?] at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:200) ~[?:?] at org.openhab.binding.hydrawise.internal.handler.HydrawiseAccountHandler.poll(HydrawiseAccountHandler.java:183) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:834) [?:?]

[digitaldan]

Well, that stack trace makes a whole lot more sense. This is actually another bug that was reported on the forums that i have a fix for but have not yet submitted a PR for. I'll get a new build posted sometime this week and a PR shortly after.

[BillGOH]

@digitaldan After one week of testing with TRACE logging I have the following result (not sure whether it is a bug or just a specific problem with my installation): After enabling TRACE logging nothing happened, so I did disable and enable the account thing and got ONE successful connection with the expected results, then nothing happened, esp. no refresh after 60 sec.

So I set the refresh interval to 65 sec. and so far it is working.