BobRak / OpenHAB-Smartthings

53 stars 54 forks source link

Smartthings Binding not working since updating to 2.5.1 #84

Closed csm0042 closed 4 years ago

csm0042 commented 4 years ago

I recently updated to OpenHAB 2.5.1 and since then my smartthings binding isn't fully working. I've been using it without issue for almost a year until now. All of my things and items are configured via files (not discovery) if that matters.

Things that still work: 1) It will discover devices (tested using an extra device I removed from my config files) 2) It will log when a device status changes (tested by toggling devices manually or via smartthings app)

What does not work: 1) I cannot send commands to devices from within OpenHAB via any means (PaperUI, HABPanel, or rules). Any attempts to do so results in an error in the log like the following:

2020-01-26 09:14:53.486 [INFO ] [ings.handler.SmartthingsThingHandler] - Attempt to send command to the Smartthings hub failed with: {} java.util.concurrent.TimeoutException: Total timeout 3000 ms elapsed at org.eclipse.jetty.client.HttpDestination$TimeoutTask.onTimeoutExpired(HttpDestination.java:529) ~[?:?] at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_191] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_191] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_191] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

csm0042 commented 4 years ago

Solved my own problem. Missed the step of coping the new .jar file over to /usr/share/openhab2/addons

BobRak commented 4 years ago

Thanks for letting me know.

csm0042 commented 4 years ago

Spoke too soon. Still polling, but still unable to send commands. Not sure what happened. Exact same error in logs as before.

BobRak commented 4 years ago

Please double check the Smartthing installation document (here). And, in particular check the Create the Device section. Make sure the device network ID is the mac address of your openhab server and mac in the preferences is your openhab server mac. It uses this to know where to respond to.

And, while you are checking verify the IP and Port in the .things file is correct.

Also, I've had others that have had the same problems and they say eventually everything starts working with no changes. Might try restarting your ST hub and openhab servers.

Let me know.

Bob

csm0042 commented 4 years ago

Ok, here's what I've done so far: 1) I re-copied/pasted the code for the OpenHabAppV2, saved, and re-published 2) I re-copied/pasted the code for the OpenHabDeviceHandler, saved, and re-published 3a) I deleted out the old device from "My Devices", 3b) waited for it to update on the smarthings app on my phone to make sure it was gone, 3c) added the OpenHabDevice back in per the instructions 3d) re-lined the smartApp in the Smartthings app 4) Confirmed IP address and port are still good in my .things file Bridge smartthings:smartthings:fb495563 [ smartthingsIp="192.168.86.4" , smartthingsPort=39500 ] { 5) Finally did a reboot of both my server and the smartthings hub. No help.

Using the live logger on the smartthings developer page, I can see that any time I use the smartthings app to send a command, there is traffic seen forwarded to OpenHab. I can confirm that the buttons in HABPanel do change to reflect the new device state. Ditto when I manually turn on/off a device from the actual device itself, OpenHab is getting a message from the hub indicating the new device state and my rules trigger as usual. I just can't initiate any commands from the OpenHab server. Likewise, none of my rules actually cause anything to happen.

Usually, the error message I get in the openhab.log file is as follows: 2020-01-26 18:25:48.065 [INFO ] [ings.handler.SmartthingsThingHandler] - Attempt to send command to the Smartthings hub failed with: {} java.util.concurrent.TimeoutException: Total timeout 3000 ms elapsed at org.eclipse.jetty.client.HttpDestination$TimeoutTask.onTimeoutExpired(HttpDestination.java:529) ~[?:?] at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_191] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_191] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_191] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191]

However occasionally, it gives a longer error as follows: 2020-01-26 18:24:42.579 [INFO ] [ings.handler.SmartthingsThingHandler] - Attempt to send command to the Smartthings hub failed with: {} java.util.concurrent.ExecutionException: java.net.NoRouteToHostException: No route to host at org.eclipse.jetty.client.util.FutureResponseListener.getResult(FutureResponseListener.java:118) ~[bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.util.FutureResponseListener.get(FutureResponseListener.java:101) ~[bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.HttpRequest.send(HttpRequest.java:685) ~[bundleFile:9.4.20.v20190813] at org.openhab.binding.smartthings.internal.SmartthingsHttpClient.sendDeviceCommand(SmartthingsHttpClient.java:63) ~[bundleFile:?] at org.openhab.binding.smartthings.handler.SmartthingsThingHandler.handleCommand(SmartthingsThingHandler.java:114) [bundleFile:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_191] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_191] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_191] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_191] at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?] at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?] at com.sun.proxy.$Proxy327.handleCommand(Unknown Source) [?:?] at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:74) [bundleFile:?] at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_191] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_191] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_191] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_191] at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?] at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_191] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_191] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_191] Caused by: java.net.NoRouteToHostException: No route to host at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:1.8.0_191] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717) ~[?:1.8.0_191] at org.eclipse.jetty.io.SelectorManager.doFinishConnect(SelectorManager.java:355) ~[?:?] at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:223) ~[?:?] at org.eclipse.jetty.io.ManagedSelector.access$1500(ManagedSelector.java:61) ~[?:?] at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:533) ~[?:?] at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:395) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135) ~[?:?] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?] at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?] ... 1 more

Haven't found any rhyme or reason yet to the extended error in the logs. All out of ideas at the moment, java is not my area of expertise!

Chris Maue Email: csmaue@gmail.com

On Sun, Jan 26, 2020 at 4:48 PM Bob Raker notifications@github.com wrote:

Please double check the Smartthing installation document (here https://github.com/BobRak/OpenHAB-Smartthings/blob/master/org.openhab.binding.smartthings/SmartthingsInstallation.md). And, in particular check the Create the Device section. Make sure the device network ID is the mac address of your openhab server and mac in the preferences is your openhab server mac. It uses this to know where to respond to.

And, while you are checking verify the IP and Port in the .things file is correct.

Also, I've had others that have had the same problems and they say eventually everything starts working with no changes. Might try restarting your ST hub and openhab servers.

Let me know.

Bob

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/BobRak/OpenHAB-Smartthings/issues/84?email_source=notifications&email_token=ACJEECCUVV3VMWQNYWY7ZULQ7YHMDA5CNFSM4KLXN5Z2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEJ575CA#issuecomment-578551432, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACJEECE33KMPMDCZBXADKJDQ7YHMDANCNFSM4KLXN5ZQ .

BobRak commented 4 years ago

Chris: I'm not sure if this is something that I have done in my code or if the issues relate to something going on in the openHAB code. I had hoped to submit this binding to openHAB almost a year ago with the hopes it would be added to openHAB. The reviewer came back with a lot of comments and one of them was related to how I was sending requests to the ST hub. Unfortunately at the same time the openHAB community was redoing the development process. I went many months without a stable development environment and eventually just gave up. Then I moved from Washington to California and that has sucked up all of my time. But recently I've picked up the development again.

The errors you are seeing indicates that the Smartthings binding isn't able to send messages to the ST hub. Again, not sure if that is something I'm doing or if it is in openHAB code. I suspect the latter. But I have a new binding jar file that uses a different technique to send message to the hub. This technique was recommended by the openHAB developers. I've put a new jar file here. Can you download it and give it a try. Before adding it to your addons directory remove the existing one.

Also, there is another user that was having similar problems. Have a look at what he did: here

csm0042 commented 4 years ago

Will do. I'll try it as soon as I get home from work this evening.

Chris Maue Email: csmaue@gmail.com

On Mon, Jan 27, 2020 at 12:14 PM Bob Raker notifications@github.com wrote:

Chris: I'm not sure if this is something that I have done in my code or if the issues relate to something going on in the openHAB code. I had hoped to submit this binding to openHAB almost a year ago with the hopes it would be added to openHAB. The reviewer came back with a lot of comments and one of them was related to how I was sending requests to the ST hub. Unfortunately at the same time the openHAB community was redoing the development process. I went many months without a stable development environment and eventually just gave up. Then I moved from Washington to California and that has sucked up all of my time. But recently I've picked up the development again.

The errors you are seeing indicates that the Smartthings binding isn't able to send messages to the ST hub. Again, not sure if that is something I'm doing or if it is in openHAB code. I suspect the latter. But I have a new binding jar file that uses a different technique to send message to the hub. This technique was recommended by the openHAB developers. I've put a new jar file here https://github.com/BobRak/Test. Can you download it and give it a try. Before adding it to your addons directory remove the existing one.

Also, there is another user that was having similar problems. Have a look at what he did: here https://github.com/BobRak/OpenHAB-Smartthings/issues/78

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/BobRak/OpenHAB-Smartthings/issues/84?email_source=notifications&email_token=ACJEECHIJTUP4DJTHLCWJ2DQ74P7XA5CNFSM4KLXN5Z2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEKAQG6Q#issuecomment-578880378, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACJEECDAJFZ5YTGSDRATBXTQ74P7XANCNFSM4KLXN5ZQ .

csm0042 commented 4 years ago

Bob, Ok, so long-story-short, it's now working. Here are the steps it took to get it there:

Step 1 (no beneficial effect) 1) Stopped openhab service 2) Removed the original .jar file from the addons folder 3) Copied over the new .jar file you directed me to 4) noticed that in the process of coping over, while all other files in the addons folder were owned by openhab:openhab, the new jar file was owned by root:root. To avoid access issues, I used chown to change the owner of the .jar file to openhab:openhab 5) Restarted the service, got a lot of errors in the log about being unable to unregister the handler. Did a reboot of the server and that cleared those up. End result was a system that functioned identical to before. Could see status updates coming in from the hub, but couldn't send out commands

Step 2 (no beneficial effect - sorta) 1) Again, stopped openhab service on my VM (I'm running openhab in an otherwise clean Ubuntu server install running on a vm) 2) Struggled a bit to delete the handler and app. I had to delete the app from the smartthings app on my phone first before it would let me delete it on the developer page. Likewise I had to delete the openhab device from my device tree before I could delete the handler. 3) Once I was sure everything was deleted, I cycled power on the hub 4) Once I was sure it was powered back up and communicating, I re-installed the app, handler, and device per the original setup instructions 5) Enabled the app in the smartthings app on my phone (the new app BTW, not the legacy one so yay, that works) 6) Once this was all done, I tried to toggle some devices and found that not only could I still not send commands, but now status messages were not coming in anymore either.

Step 3 (this fixed it) 1) Fiddled around a bit and then decided to remove a device from my "things" configuration to see if smartthings could discover it on its own 2) Device was discovered and here is the kicker. At some point during either the deletion or the new setup, my hub name changed from the fxxxxx generic serial number it had before to "Home". I could see this once smartthings found my test device and I could view the device address it found it at. (I usually have all my devices hard-coded via things and items files). 3) I updated my things and items files to reflect the new hub name of "Home", and everything took off working again.

Summary So here is the thing. Since I don't know what step caused the hub name to change, I have no way of knowing if that maybe was the issue all along, or if that was a side effect of blowing away the old config and setting it up again. I tend to believe the latter since when the hub name was wrong, I wasn't even getting status updates, but again, I cannot be 100% sure.

In any case, it's been working flawlessly all evening since around 6pm CST when I found and fixed the hub name in my config files. This is all using your "test" .jar file as well, not the original. Response is nice and snappy and it even seems like there is a slight decrease in the lag I'm used to between hitting the button in HABPanel and the actual device reacting, but it's very possible that's my imagination. I do have a couple of rules where the manual triggering of one device causes another to automatically turn on (bathroom light + fan), which requires a full round trip status message, rule to process, then command to be sent and that round-trip time seems particularly snappy now relative to before.

I plan to continue to run your new "test" instance for as long as it continues to work. If anything weird comes up, I'll let you know. I appreciate the help!

Chris Maue Email: csmaue@gmail.com

On Mon, Jan 27, 2020 at 3:29 PM Christopher Maue csmaue@gmail.com wrote:

Will do. I'll try it as soon as I get home from work this evening.

Chris Maue Email: csmaue@gmail.com

On Mon, Jan 27, 2020 at 12:14 PM Bob Raker notifications@github.com wrote:

Chris: I'm not sure if this is something that I have done in my code or if the issues relate to something going on in the openHAB code. I had hoped to submit this binding to openHAB almost a year ago with the hopes it would be added to openHAB. The reviewer came back with a lot of comments and one of them was related to how I was sending requests to the ST hub. Unfortunately at the same time the openHAB community was redoing the development process. I went many months without a stable development environment and eventually just gave up. Then I moved from Washington to California and that has sucked up all of my time. But recently I've picked up the development again.

The errors you are seeing indicates that the Smartthings binding isn't able to send messages to the ST hub. Again, not sure if that is something I'm doing or if it is in openHAB code. I suspect the latter. But I have a new binding jar file that uses a different technique to send message to the hub. This technique was recommended by the openHAB developers. I've put a new jar file here https://github.com/BobRak/Test. Can you download it and give it a try. Before adding it to your addons directory remove the existing one.

Also, there is another user that was having similar problems. Have a look at what he did: here https://github.com/BobRak/OpenHAB-Smartthings/issues/78

— You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub https://github.com/BobRak/OpenHAB-Smartthings/issues/84?email_source=notifications&email_token=ACJEECHIJTUP4DJTHLCWJ2DQ74P7XA5CNFSM4KLXN5Z2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEKAQG6Q#issuecomment-578880378, or unsubscribe https://github.com/notifications/unsubscribe-auth/ACJEECDAJFZ5YTGSDRATBXTQ74P7XANCNFSM4KLXN5ZQ .