goedh452 / homebridge-http-sprinkler

Homebridge http controlled sprinkler
Apache License 2.0
12 stars 6 forks source link

Sprinkler stuck on “Stopping...” #3

Closed royby12 closed 6 years ago

royby12 commented 6 years ago

Hi, First, thank you for this awesome awesome plugin!! I’ve been looking for some thing like it!! When you turn on the sprinkler it goes from off->starting...->running As long as you in the app it’s all good, but when you leave the home app and turning it on again It will go into “stopping...” and buffer antil the timer will finish... it no longer display the “running” status and the time left.

I see no calls in the homebridge log when opening the app to get the status.

Any idea what can cause this?

goedh452 commented 6 years ago

Hi!

Are you using status polling? I do so every 5 seconds the status is checked in domoticz and corrected in the home app.

I checked the problem you are experiencing and see that when the sprinkler is on and I close and reopen the home app, the status is “stopping” indeed. Than the status polling corrects it.

royby12 commented 6 years ago

Hi, yes, I’m using polling with interval of 3 seconds. I’m using Tasmota and I can see the request coming to it in the tasmota console every 3 sec but the home app still buffer on “Stopping” The status url, jsonPath, on and off values seems correct because when I’m turning the switch off outside the homebridge/home app the status at the app is corrected to off and when I’m turning it on from the tasmota interface it again getting to “stopping” mode.

goedh452 commented 6 years ago

Ok, that's strange then.

I made some changes to the code. Could you please try it by installing it in the modules directory with

cd /usr/lib/node_modules sudo npm install -g git+https://github.com/goedh452/homebridge-http-sprinkler.git

royby12 commented 6 years ago

Unfortunately I still have the same behavior. Ca you add more logs? What I see now is only when turning it on or off: [15/09/2018, 15:51:32] [Boiler] HTTP power function succeeded! [15/09/2018, 15:51:35] [Boiler] State is currently: ON Valve Remaining Duration changed to: 3600 Turning Valve Boiler on with Timer set to: 3600 seconds

[15/09/2018, 15:52:57] [Boiler] Setting power state to off [15/09/2018, 15:52:57] [Boiler] HTTP power function succeeded! [15/09/2018, 15:52:59] [Boiler] State is currently: OFF Valve Remaining Duration changed to: 0

goedh452 commented 6 years ago

I added some logging. Please try again and copy paste the logging result here. I added some logging on the startup of the plugin as well, so please also paste the loggin of the plugin when homebridge starts up. This logging is spooled before homebridge is started up completely and can be found right above the section with the pincode. This part contains the values of the config that is received.

royby12 commented 6 years ago

More logs indeed :) These are the logs: On Start up: [16/09/2018, 19:03:49] [Boiler] Initializing HttpSprinkler accessory... [16/09/2018, 19:03:49] [Boiler] NAME: Boiler [16/09/2018, 19:03:49] [Boiler] ICON: 0 [16/09/2018, 19:03:49] [Boiler] ON URL: http://192.168.1.129/cm?cmnd=Power%20On [16/09/2018, 19:03:49] [Boiler] OFF URL: http://192.168.1.129/cm?cmnd=Power%20Off [16/09/2018, 19:03:49] [Boiler] CHECKSTATUS: polling [16/09/2018, 19:03:49] [Boiler] POLLINGINTERVAL: 3000 [16/09/2018, 19:03:49] [Boiler] STATUS URL: http://192.168.1.129/cm?cmnd=Power [16/09/2018, 19:03:49] [Boiler] JSON PATH: POWER [16/09/2018, 19:03:49] [Boiler] ON VALUE: ON [16/09/2018, 19:03:49] [Boiler] OFF VALUE: OFF [16/09/2018, 19:03:49] [Boiler] USE TIMER: yes [16/09/2018, 19:03:49] [Boiler] DEFAULT TIME: 3600 [16/09/2018, 19:03:49] [Boiler] HTTP MEDTHOD: GET [16/09/2018, 19:03:49] [Boiler] FUNCTION: getServices [16/09/2018, 19:03:49] [Boiler] Check status: polling [16/09/2018, 19:03:50] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:03:50] [Boiler] ON VALUE: ON [16/09/2018, 19:03:50] [Boiler] OFF VALUE: OFF [16/09/2018, 19:03:50] [Boiler] JSON PATH: json.POWER [16/09/2018, 19:03:50] [Boiler] JSON: {"POWER":"OFF"} [16/09/2018, 19:03:50] [Boiler] State is currently: OFF On going log: [16/09/2018, 19:03:53] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:03:56] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:03:59] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:02] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:05] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:08] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:11] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:14] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:17] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:04:20] [Boiler] FUNCTION: httpRequest ... ...

When turning on: [16/09/2018, 19:11:29] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:11:32] [Boiler] FUNCTION: setPowerStatePolling [16/09/2018, 19:11:32] [Boiler] Setting power state to on [16/09/2018, 19:11:32] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:11:32] [Boiler] HTTP power function succeeded! [16/09/2018, 19:11:32] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:11:32] [Boiler] ON VALUE: ON [16/09/2018, 19:11:32] [Boiler] OFF VALUE: OFF [16/09/2018, 19:11:32] [Boiler] JSON PATH: json.POWER [16/09/2018, 19:11:32] [Boiler] JSON: {"POWER":"ON"} [16/09/2018, 19:11:32] [Boiler] State is currently: ON Valve Remaining Duration changed to: 3600 Turning Valve Boiler on with Timer set to: 3600 seconds [16/09/2018, 19:11:35] [Boiler] FUNCTION: httpRequest When re-opening the app there is nothing for that accessory besides the on going http requests: [16/09/2018, 19:12:05] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:08] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:11] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:14] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:17] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:20] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:23] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:26] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:29] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:32] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:35] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:38] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:12:41] [Boiler] FUNCTION: httpRequest

When turning off: [16/09/2018, 19:13:29] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:13:32] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:13:34] [Boiler] FUNCTION: setPowerStatePolling [16/09/2018, 19:13:34] [Boiler] Setting power state to off [16/09/2018, 19:13:34] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:13:34] [Boiler] HTTP power function succeeded! [16/09/2018, 19:13:35] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:13:35] [Boiler] ON VALUE: ON [16/09/2018, 19:13:35] [Boiler] OFF VALUE: OFF [16/09/2018, 19:13:35] [Boiler] JSON PATH: json.POWER [16/09/2018, 19:13:35] [Boiler] JSON: {"POWER":"OFF"} [16/09/2018, 19:13:35] [Boiler] State is currently: OFF Valve Remaining Duration changed to: 0 [16/09/2018, 19:13:38] [Boiler] FUNCTION: httpRequest [16/09/2018, 19:13:41] [Boiler] FUNCTION: httpRequest

royby12 commented 6 years ago

I've tried to set the checkstatus to "once" and with that configuration it seems to update the status fine. With "once" I've saw this line in the log: [16/09/2018, 20:13:12] [Boiler] FUNCTION: getPowerState [16/09/2018, 20:13:12] [Boiler] FUNCTION: httpRequest [16/09/2018, 20:13:12] [Boiler] status received from: http://192.168.1.129/cm?cmnd=Power state is currently: true

I haven't seen it when I used "polling".

Though with this configuration it seems to reset the count every time I open the app

goedh452 commented 6 years ago

There seems to be a problem with the polling indeed. My log show the function httprequest and besides that the result On or Off. That last part is missing in your log and therefor the stopping isn’t corrected by the polling. I’ll dive into it in the coming days. I think polling throws an error and the function is therefore aborted. I’ll let you know when I made some changes!

goedh452 commented 6 years ago

So, I added some more logging in the code that doesn't seem to work in your case. Could you try again and post the logging? Especially the ongoing log is interesting.

I also checked the code when polling is set to "once". That code retrieves the status in a different way which is less robust. It checks if the status does not equal the offValue. Since the problem seems to be with your onValue it is clear why polling once does work. Downside is it does actually poll once. So when you operate the sprinkler with the app open, the app status is not updated.

I would like to give the current polling mechanism one more try :-)

royby12 commented 6 years ago

Hi, Thanks!!

These are the ongoing logs: [17/09/2018, 19:48:47] [Boiler] FUNCTION: httpRequest [17/09/2018, 19:48:47] [Boiler] POLLING: no error [17/09/2018, 19:48:52] [Boiler] FUNCTION: httpRequest [17/09/2018, 19:48:52] [Boiler] POLLING: no error [17/09/2018, 19:48:57] [Boiler] FUNCTION: httpRequest

Its just keep going and going, still the same result -> it getting stuck on Stopping... P.S - the remaining time keep to reset every time, but that is a different issue.

goedh452 commented 6 years ago

I'm running a bit out of options. The problem is the longpolling event doesn't get to the function that has the be called when polling. It works fine for mee and I see the logging there in my console output. Is it possible the result of the status URL takes to long; longer than 3 seconds? Maybe set it to 5 or 10 and see if that helps.

The reset of the timer is a bug in the home app. I cannot solve it in my code.

goedh452 commented 6 years ago

Wait, just added one more thing. I removed a lot of logging and added one more on a different spot. It you want, you can try it and post the ongoing log again. If you're getting tired of it, no hard feelings. I can image.

royby12 commented 6 years ago

Dude! I'm with you all the way :) Appreciate your work here!!! The response from the Sonoff takes approximately ~60 ms.

This is the log after your new change: [17/09/2018, 20:45:35] [Boiler] BODY: {"POWER":"ON"} [17/09/2018, 20:45:40] [Boiler] BODY: {"POWER":"ON"} [17/09/2018, 20:45:45] [Boiler] BODY: {"POWER":"ON"} [17/09/2018, 20:45:50] [Boiler] BODY: {"POWER":"ON"} [17/09/2018, 20:45:55] [Boiler] BODY: {"POWER":"ON"} [17/09/2018, 20:46:00] [Boiler] BODY: {"POWER":"ON"} [17/09/2018, 20:46:05] [Boiler] BODY: {"POWER":"ON"}

Any chance the parsing cause the problem? BTW When the switch is OFF and I open the app I immediately see it is off on the app. When the switch is On it goes immediately to Stopping and stuck there...

P.S - Reg the remaining time I think there is a way to solve it but different issue different thread :)

goedh452 commented 6 years ago

I think I solved the issue. The function that is polling is only executed when the data differs from the previous poll. In my case the JSON result contains a timestamp and thus is always different from the previous one. In your case not. I changed the polling mechanism is a way the function is always executed.

I hope this solves it for you as well!

And of course I'm curious how to fix the timer issue.

royby12 commented 6 years ago

Oh ya man! Solved!!! [17/09/2018, 21:36:21] [Boiler] State is currently: ON [17/09/2018, 21:36:26] [Boiler] State is currently: ON

I think you can remove logs now and close the issue :) Now when I re-open the app it change to Running.

As for the remaining time -> I'll try to gather some info first :)

goedh452 commented 6 years ago

Nice! I’ll remove the logs later and push a new version to npm.

Thanks for testing!