Smartthings Binding working intermittantly

[jjam8644]

Thank you for your Smartthings binding I have installed it on an OpenHABian (v2.5 testing) device.(Raspberry Pi B). The issue is the commands sent to my ST Hub work intermittently. her is an example where the switch turned off, then on, but failed to turn back off again. These failures are happening even on the first attempt on a quite device. The ST hub responds to the successful events, but logs nothing for the timeout failures.

Any advice would be appreciated. Here are my OH and ST logs: OH:

2019-06-08 16:42:27.801 [ome.event.ItemCommandEvent] - Item 'Office_Lights_Switch' received command OFF

2019-06-08 16:42:27.811 [nt.ItemStatePredictedEvent] - Office_Lights_Switch predicted to become OFF

2019-06-08 16:42:27.845 [vent.ItemStateChangedEvent] - Office_Lights_Switch changed from ON to OFF

2019-06-08 16:42:27.848 [GroupItemStateChangedEvent] - Office_Group changed from ON to OFF through Office_Lights_Switch

==> /var/log/openhab2/openhab.log <==

2019-06-08 16:42:28.094 [INFO ] [hings.internal.SmartthingsHttpClient] - Sent message "{"capabilityKey": "switch", "deviceDisplayName": "Office Lights", "capabilityAttribute": "switch", "value": "off"}" with path "/update" to the Smartthings hub, recieved HTTP status 202

==> /var/log/openhab2/events.log <==

2019-06-08 16:42:52.818 [ome.event.ItemCommandEvent] - Item 'Office_Lights_Switch' received command ON

2019-06-08 16:42:52.839 [nt.ItemStatePredictedEvent] - Office_Lights_Switch predicted to become ON

2019-06-08 16:42:52.843 [vent.ItemStateChangedEvent] - Office_Lights_Switch changed from OFF to ON

2019-06-08 16:42:52.847 [GroupItemStateChangedEvent] - Office_Group changed from OFF to ON through Office_Lights_Switch

==> /var/log/openhab2/openhab.log <==

2019-06-08 16:42:53.076 [INFO ] [hings.internal.SmartthingsHttpClient] - Sent message "{"capabilityKey": "switch", "deviceDisplayName": "Office Lights", "capabilityAttribute": "switch", "value": "on"}" with path "/update" to the Smartthings hub, recieved HTTP status 202

2019-06-08 16:42:53.797 [DEBUG] [rtthings.internal.SmartthingsServlet] - Smartthings servlet service() called with: 192.168.0.23: POST /smartthings/state

2019-06-08 16:42:53.801 [DEBUG] [rtthings.internal.SmartthingsServlet] - Smartthing servlet function requested: state with Method: POST

2019-06-08 16:42:53.809 [DEBUG] [ings.handler.SmartthingsThingHandler] - Smartthings updated State for channel: smartthings:switch:6a7f2c1e:Office_Lights:switch to ON

2019-06-08 16:42:53.814 [DEBUG] [ings.handler.SmartthingsThingHandler] - State timing data, Request time until data received and processed 0, Hub processing time: 82 

==> /var/log/openhab2/events.log <==

2019-06-08 16:43:03.676 [me.event.ThingUpdatedEvent] - Thing 'milight:bridgeV6:98D86335C392' has been updated.

2019-06-08 16:43:10.820 [ome.event.ItemCommandEvent] - Item 'Office_Lights_Switch' received command OFF

2019-06-08 16:43:10.831 [nt.ItemStatePredictedEvent] - Office_Lights_Switch predicted to become OFF

2019-06-08 16:43:10.849 [vent.ItemStateChangedEvent] - Office_Lights_Switch changed from ON to OFF

2019-06-08 16:43:10.855 [GroupItemStateChangedEvent] - Office_Group changed from ON to OFF through Office_Lights_Switch

==> /var/log/openhab2/openhab.log <==

2019-06-08 16:43:13.836 [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.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:52) ~[?:?]

    at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:271) ~[?:?]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]

    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:?]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:?]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]

    at java.lang.Thread.run(Thread.java:748) [?:?]

ST:

4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:53 AM: debug Msg '[index:4D, mac:B827EBBA7332, ip:C0A80004, port:1F90, requestId:6d51832a-eec2-4fa4-b944-7e2c9937ea4a, headers:[content-length:0, http/1.1 200 ok:null, server:Jetty(9.4.12.v20180830)], body:null, header:HTTP/1.1 200 OK 
Content-Length: 0 
Server: Jetty(9.4.12.v20180830), status:200]'
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:53 AM: debug Forwarding device event to openhabDevice: {"path":"/smartthings/state","hubStartTime":1560012173653,"body":{"deviceDisplayName":"Office Lights","value":"on","capabilityAttribute":"switch","hubTime":"--hubTime--"}}
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:53 AM: debug Entered input handler for "Office Lights" with attribute "switch" changed to "on"
4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:53 AM: debug hub elapsed time is 82
4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:53 AM: debug Sending '{"path":"/smartthings/state","hubStartTime":1560012173653,"body":{"deviceDisplayName":"Office Lights","value":"on","capabilityAttribute":"switch","hubTime":"--hubTime--"}}' to 192.168.0.4:8080 with mac: B8:27:EB:BA:73:32
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:53 AM: debug openhabUpdateHandler - Capability Switch with device name Office Lights changed to on using action actionOnOff
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:53 AM: debug Received update event from openhabDevice: [capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, hubStartTime:1560012172964, openHabStartTime:null, path:update, value:on]
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:53 AM: debug Received device event from Message : [capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, hubStartTime:1560012172964, openHabStartTime:null, path:update, value:on]
4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:52 AM: debug Creating event with message: [capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, hubStartTime:1560012172964, openHabStartTime:null, path:update, value:on]
4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:52 AM: debug Msg '[index:4C, mac:B827EBBA7332, headers:[content-length:113, accept-encoding:gzip, post /update http/1.1:null, host:192.168.0.23:39500, user-agent:Jetty/9.4.12.v20180830, content-type:application/json], body:{"capabilityKey": "switch", "deviceDisplayName": "Office Lights", "capabilityAttribute": "switch", "value": "on"}, header:POST /update HTTP/1.1 
Accept-Encoding: gzip 
User-Agent: Jetty/9.4.12.v20180830 
Content-Type: application/json 
Host: 192.168.0.23:39500 
Content-Length: 113, data:[capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, value:on], json:[capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, value:on]]'
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:28 AM: debug openhabUpdateHandler - Capability Switch with device name Office Lights changed to off using action actionOnOff
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:28 AM: debug Received update event from openhabDevice: [capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, hubStartTime:1560012148000, openHabStartTime:null, path:update, value:off]
0275be5d-a62b-49c7-9109-1e9664df3273  9:42:28 AM: debug Received device event from Message : [capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, hubStartTime:1560012148000, openHabStartTime:null, path:update, value:off]
4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:28 AM: debug Creating event with message: [capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, hubStartTime:1560012148000, openHabStartTime:null, path:update, value:off]
4d6f971e-f1ff-4104-8a3a-72a158ec411c  9:42:28 AM: debug Msg '[index:4A, mac:B827EBBA7332, headers:[content-length:114, accept-encoding:gzip, post /update http/1.1:null, host:192.168.0.23:39500, user-agent:Jetty/9.4.12.v20180830, content-type:application/json], body:{"capabilityKey": "switch", "deviceDisplayName": "Office Lights", "capabilityAttribute": "switch", "value": "off"}, header:POST /update HTTP/1.1 
Accept-Encoding: gzip 
User-Agent: Jetty/9.4.12.v20180830 
Content-Type: application/json 
Host: 192.168.0.23:39500 
Content-Length: 114, data:[capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, value:off], json:[capabilityAttribute:switch, capabilityKey:switch, deviceDisplayName:Office Lights, value:off]]'

[BobRak]

Sorry I don't have any idea why this is happening. I have not seen this myself and haven't had other people report similar issues. I'm surprised at the timeout. ST doesn't work like a normal http server. A normal http server receives a request, processes it and then sends a response with an http 200 code. ST immediately responds with an HTTP 202. Then when it is done it sends a message back to OpenHAB as separate message. Therefore the hub always responds quickly even if it takes a while to process.

Are you using a ST v3 hub? I have a V2 hub.

Right now I don't have a working development environment. OpenHAB is reworking the build process and development tools and I am not currently able to build and therefore have no ability to test. Once I can put together a working development environment I can do some testing on my end.

My production environment which is RPi 3 is on openhab 2.4. I'm not seeing any timeout's there.

I'm not optimistic it would make a difference but is it possible for you to try openhab 2.4. You say you are on a testing version. If it is reasonably easy to change versions that might be worth a try.

Bob

[jjam8644]

Thanks for the reply. I have the ST v2 hub as well. I went to the OH v2.5 test as some of my motion sensors were not being recognized in 2.4. I am still in pre-installation testing until I can get this stabilized, so I will try going back to v2.4 and trying it with just the one Binding & just one Thing.

FWIW, used both a Pi 3B and then moved to a 3B+ to see that would help with the timeout issue.

I understand your point about the ST hub's unique response methodology, but when the timeouts occur, nothing at all appears to happen on the ST hub or is even recorded on the ST log. I think the failure is somewhere in the ST Binding-Jetty process within the OH environment.

I'll keep you updated on what I find.

[jjam8644]

OK, clean install of Openhabian 2.4 Stable on Pi 3B+. Installed just the Smartthings binding with one switch (1 thing/1 item). I am still getting the same intermittent result with Jetty timeout exception as noted in my first post.

[BobRak]

@jjam8644 Sorry I have no idea why this is happening. The reference to Jetty in the timeout exception does make me think it is related to network IO. But the timeout is java.util.concurrent.TimeoutException opposed to a SocketTimeout. Maybe this is how Jetty works.

I'm not seeing any similar timeouts in my production environment which is on openHAB 2.4.0-1.

Any chance you are having network issues between openHAB and your hub? Have you rebooted your hub? On you RPi are you using the wired or wireless network? Are you sure the mac address in your config on the RPi is correct. I suspect you have tried these things but I don't have any better ideas.

[jjam8644]

After revising the OH server didn't work, I I decided to do the same to the ST hub. I deleted all my ST Smart Apps And Device Handlers, rebooted my ST Hub and reloaded the Smart Apps and Device Handlers.

Everything is now working! Thanks for the help.

[BobRak]

Thanks for letting me know. Sooner or later I plan to write an FAQ and will definitely include your experience.

[pocupine]

Hi James,

Are you getting the same problem again? I have this problem. The communication works most of the time but it stops very randomly.

Clement

[jjam8644]

No issues since I reset the ST Hub to the factory defaults and reloaded everything.

On Tue, Jul 16, 2019 at 11:42 PM pocupine notifications@github.com wrote:

Hi James,

Are you getting the same problem again? I have this problem. The communication works most of the time but it stops very randomly.

Clement

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/BobRak/OpenHAB-Smartthings/issues/78?email_source=notifications&email_token=ADRNCZAQDABZW4TF6USLOIDP725PFA5CNFSM4HWHUT6KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD2DGSWA#issuecomment-512125272, or mute the thread https://github.com/notifications/unsubscribe-auth/ADRNCZHOXBMJ65W2KKPJRQ3P725PFANCNFSM4HWHUT6A .

[edwolfe3]

I'm having a timeout issue as well

[iscovery.SmartthingsDiscoveryService] - Attempt to send command to the Smartthings hub failed with: Total timeout 3000 ms elapsed

I double checked the installation instructions. Any resolution in the works?

OpenHAB 2.5.5 release build Smartthings Binding: 2.5.5.202006040007 New Install using Openhabian on Raspi 4 with 4gb RAM

[BobRak]

This is a local issue to your installation.

1. Can you ping the Smartthings hub from your openhab server?
2. Is the smartthingsIp in the .things file right?
3. Is the ip in ST IDE device (OpenHabDev) set and does it point back to the openhab server

I am working through the comments from the openhab maintainers and expect to be at that for a while. When I'm done with I will put a new release in the github

[edwolfe3]

Yes to all questions.

Get Outlook for Android

On Sun, Jun 21, 2020 at 1:27 PM -0400, "Bob Raker" notifications@github.com wrote:

Reopened #78.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or unsubscribe.

[BobRak]

I don't know what to suggest. I'll have a new build in a week or so.