Timing out on IHC Binding

I´m experience the same problem now. Rebooting my Openhab (Rpi3) solve the problem, but only for some hours, then I experiences the problem again…
This mainly happens when OpenHab send commands to the IHC controller, not when receiving.
I have quite some receiving going on, as OpenHab read 12 IHC temperature sensors, as well as light status. And then I have one rule where a motion sensor (zwave) activate a light. And it´s when the motion sensor is triggering I experience the error.

This has been working for quite some time now without problems, and the I noticed the problem a coupple of days ago. I have not found a solution. And I have no idea what this start to happen.

Here are my logfile:

2018-04-23 21:44:25.285 [ERROR] [nhab.binding.ihc.internal.IhcBinding] - Can't update Item 'garage_zwave_pir' value 

org.openhab.binding.ihc.ws.IhcExecption: org.apache.http.conn.ConnectTimeoutException: Connect to 10.4.28.6:777 [/10.4.28.6] failed: Read timed out

	at org.openhab.binding.ihc.ws.IhcHttpsClient.sendQuery(IhcHttpsClient.java:103) [224:org.openhab.binding.ihc:1.11.0]

	at org.openhab.binding.ihc.ws.IhcResourceInteractionService.resourceQuery(IhcResourceInteractionService.java:78) [224:org.openhab.binding.ihc:1.11.0]

	at org.openhab.binding.ihc.ws.IhcClient.getResourceValueInformation(IhcClient.java:434) [224:org.openhab.binding.ihc:1.11.0]

	at org.openhab.binding.ihc.internal.IhcBinding.updateResource(IhcBinding.java:406) [224:org.openhab.binding.ihc:1.11.0]

	at org.openhab.binding.ihc.internal.IhcBinding.internalReceiveUpdate(IhcBinding.java:359) [224:org.openhab.binding.ihc:1.11.0]

	at org.openhab.core.binding.AbstractBinding.receiveUpdate(AbstractBinding.java:113) [226:org.openhab.core.compat1x:2.2.0]

	at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractEventSubscriber.java:39) [226:org.openhab.core.compat1x:2.2.0]

	at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415) [3:org.apache.karaf.services.eventadmin:4.1.3]

	at org.apache.felix.eventadmin.impl.tasks.HandlerTask.runWithoutBlacklistTiming(HandlerTask.java:82) [3:org.apache.karaf.services.eventadmin:4.1.3]

	at org.apache.felix.eventadmin.impl.tasks.SyncDeliverTasks.execute(SyncDeliverTasks.java:104) [3:org.apache.karaf.services.eventadmin:4.1.3]

	at org.apache.felix.eventadmin.impl.tasks.AsyncDeliverTasks$TaskExecuter.run(AsyncDeliverTasks.java:166) [3:org.apache.karaf.services.eventadmin:4.1.3]

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

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

	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) [?:?]

Caused by: org.apache.http.conn.ConnectTimeoutException: Connect to 10.4.28.6:777 [/10.4.28.6] failed: Read timed out

	at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:143) ~[?:?]

	at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:353) ~[?:?]

	at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:380) ~[?:?]

	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:236) ~[?:?]

	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) ~[?:?]

	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88) ~[?:?]

	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) ~[?:?]

	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) ~[?:?]

	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82) ~[?:?]

	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55) ~[?:?]

	at org.openhab.binding.ihc.ws.IhcHttpsClient.sendQ(IhcHttpsClient.java:119) ~[?:?]

	at org.openhab.binding.ihc.ws.IhcHttpsClient.sendQuery(IhcHttpsClient.java:87) ~[?:?]

	... 15 more

Caused by: java.net.SocketTimeoutException: Read timed out

	at java.net.SocketInputStream.socketRead0(Native Method) ~[?:?]

	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:?]

	at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[?:?]

	at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:?]

	at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) ~[?:?]

	at sun.security.ssl.InputRecord.read(InputRecord.java:503) ~[?:?]

	at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) ~[?:?]

	at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1385) ~[?:?]

	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1413) ~[?:?]

	at sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1397) ~[?:?]

	at org.apache.http.conn.ssl.SSLConnectionSocketFactory.createLayeredSocket(SSLConnectionSocketFactory.java:394) ~[?:?]

	at org.apache.http.conn.ssl.SSLConnectionSocketFactory.connectSocket(SSLConnectionSocketFactory.java:353) ~[?:?]

	at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:134) ~[?:?]

	at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:353) ~[?:?]

	at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:380) ~[?:?]

	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:236) ~[?:?]

	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) ~[?:?]

	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88) ~[?:?]

	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) ~[?:?]

	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) ~[?:?]

	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82) ~[?:?]

	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:55) ~[?:?]

	at org.openhab.binding.ihc.ws.IhcHttpsClient.sendQ(IhcHttpsClient.java:119) ~[?:?]

	at org.openhab.binding.ihc.ws.IhcHttpsClient.sendQuery(IhcHttpsClient.java:87) ~[?:?]

	... 15 more

And a few minutes after, its working again, and I havn´t done anything.

2018-04-23 21:58:14.365 [vent.ItemStateChangedEvent] - ZWaveNode5ZW100MultiSensor6_BinarySensor changed from OFF to ON

2018-04-23 21:58:14.683 [vent.ItemStateChangedEvent] - ZWaveNode5ZW100MultiSensor6_MotionAlarm changed from OFF to ON

2018-04-23 21:58:14.705 [ome.event.ItemCommandEvent] - Item 'garage_zwave_pir' received command ON

2018-04-23 21:58:14.713 [vent.ItemStateChangedEvent] - garage_zwave_pir changed from OFF to ON

This has to be something with the ssl connection… Probably due to the IHC controller beeing busy or something like that. Beside Openhab I also use IHC Captain from another Rpi 3.

hi Pauli

Great Work with the IHC/ELKO binding been very happy with. It just seams like i am having some connection problems it has been working for som time and then when i updated to openhab v2.2

my setup is like this
IHC Controller HW. 6.2 SW. 2.8.4
Openhab is running on a Mac Mini
Java version 171
Network topology: Both Controller and Mac is on same ethernet switch so unless there is a firewall in my mac i dont see there should be a problem

how do i change the log level to debug?

hope this clarifies things to better solve the problem
Best Regards
Christian

how do i change the log level to debug?

You can find information from Logging | openHAB

I am also having this problem.

I’ve only just added the IHC/ELKO binding and all channels have been auto-added. But the controller keeps going from Online to Offline and back again.

My setup is this:
IHC Controller
HW 6.2 / SW 2.8.4
Openhab 2.4.0 running on Raspberry Pi 3 (Openhabian) with every component up-to-date
Everything is connected on same lan (wired).

Openhab log shows this:

2019-08-10 08:18:43.609 [hingStatusInfoChangedEvent] - ‘ihc:controller:408b20ca’ changed from OFFLINE (COMMUNICATION_ERROR): org.apache.http.conn.ConnectTimeoutException: Connect to 192.168.99.4:443 [/192.168.99.4] failed: Read timed out to OFFLINE (BRIDGE_OFFLINE): Initializing communication to the IHC / ELKO controller
2019-08-10 08:18:44.115 [me.event.ThingUpdatedEvent] - Thing ‘ihc:controller:408b20ca’ has been updated.
2019-08-10 08:18:44.387 [hingStatusInfoChangedEvent] - ‘ihc:controller:408b20ca’ changed from OFFLINE (BRIDGE_OFFLINE): Initializing communication to the IHC / ELKO controller to ONLINE
2019-08-10 08:19:00.816 [hingStatusInfoChangedEvent] - ‘ihc:controller:408b20ca’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): org.apache.http.conn.ConnectTimeoutException: Connect to 192.168.99.4:443 [/192.168.99.4] failed: Read timed out

This is just part of the log of course. It keeps spitting out errors like this.

What to do?

Mikkel

Which IHC binding are you using? You mentioned you use auto-added channels… Which, as far as I remember, indicate you´re using a newer binding, installed manually… Right?

The issue with the timeout has been reported by others as well. And I have been having the same issues lately. What I do to fix it is:
Shell into your openhab (putty/whatever).

Stop openhab2
Remove the binding from /usr/share/openhab2/addons.
Clean cache/tmp
Reboot.
Copy the binding into the /usr/share/openhab2/addons.

Then IHC binding will connect fine and keep on running. (untill I do another clear cache/tmp without removing the ihc binding first).
Whats strange is… My problems started after started all over with a fresh install of openhab 2.5M1. Before this, I had a crash on 2.5 build 1575 where the IHC binding was running highly stable.
This is the binding I´m using:

openhab> bundle:list -s |grep -i ihc
248 x Active   x  80 x 2.5.0.201904021522     x org.openhab.binding.ihc
openhab>

I believe it may be time to tag @pauli_anttila on this one.

I see from you log, that you are using v2 IHC binding, but you didn’t mentation which build version. Have you tested with latest version (e.g. 2.5.0M2)? Have you tried to increase the timeout parameter?

Pauli, which date is the latest IHC binding?
If newer than 2. april 2019, will it be available for download? I do not fancy to upgrade to 2.5M2 yet, only to get the latest IHC binding.

I have some problems with timeouts as well. Seems to happen only when I clear the cache and tmp, and reboot. Then IHC binding will timeout when openhab starts. Increasing the timeout does not help.
If I remove the IHC binding before clearing cache/tmp and reboot, and add the IHC binding again, everything works fine.

I´m not quite sure when this happened. I think it started when I moved back from a openhab 2.5 build 1575 to a new/fresh install of 2.5M1, (still using the same IHC binding though).
I´m using this version:

openhab> bundle:list -s |grep -i ihc
248 x Active   x  80 x 2.5.0.201904021522     x org.openhab.binding.ihc
openhab>

When it´s up running, it´s rock stable. Infact, IHC binding is one of the most stable bindings I´m using. Never had any issues (beside the above mentioned).

@pauli_anttila I’m completely new to openhab (and by no means an expert in shell/ssh either), so forgive my ignorance…

How do I find out which build version of the binding I am using? I’m quite sure I downloaded the latest release (whatever version that is), but maybe I found an old link?

And yes I tried increasing the timeout value, but it won’t save. Just keeps it at 5000 no matter what I put in. I hit save, but it just won’t save it.

@Kim_Andersen Yes I installed the binding manually. What I mean about “auto-added channels” is that I set openhab to set to “Simple Mode” under Item Linking.

I am considering trying Hass instead to see if that works, but I would love to get this fixed, as openhab really seems awesome.

Okay, thats not the same as auto-channel in the IHC binding… Simple mode in openhab auto-creates items, not channels.
Auto-channels in the IHC binding will create all channels from your Visual program.

Then stick to openhab :slight_smile:
You´re problem should be easy to fix…
First of all, find the version of the binding you´re using. In order to do that, you´ll need to shell into your openhab server…
If you´re using Windows, I suggest download and installing WinScp WinSCP :: Official Site :: Download
And afterwards install Putty (thats the shell/terminal). I dont recall if WinScp comes with Putty, if not, then you´ll need to download and install that as well. https://www.putty.org/

From here, these are the only two and best main utilities to use with openhab, (in my opinion)…

From within WinScp. The login appear at first. In this screen you choose New Site, and just need to enter ip of your openhab server, username and pw (pw only needed if you dont want to enter it each time) for your openhabian (server). Remember to save your settings, otherweise you´ll have to enter it each time.
This is my login screen… (Notice I dont use pre-inserted pw).
winscp%20login

When done, and you have logged in, you´ll find putty on the Commands menu (or CTRL-P). When you start Putty from there, it will use the same server settings which you´d just setup in the first login screen. And you see a typical terminal/cmd window open promting for a password. Just enter the password for your openhabian (default it´s [openhabian]).
Like this:
putty%20login

When pw entered, it will look like this:

From here, your first command is to shell into Karaf consol using:

ssh -p 8101 openhab@localhost

It will promt you for the pw, which is [habopen] by default.
Enter the pw, and it should look like this:

Now, enter one last command into the consol:

bundle:list -s |grep -i ihc

And it should look like this:

Notice the result line… This is where the version of the IHC binding is showen… As you can see, the version i´m using is:

248 x Active   x  80 x 2.5.0.201904021522     x org.openhab.binding.ihc

Thats it… You´re done, and we´re ready to help you futher.

There may be others an more simple ways to do it. And it may seem like a long way for a simple info. But I find this way highly usefull, specially because I use Winscp almost every day with openhab.
When you first get to this, you´ll be surprised how easy it really is. (And I havn´t even mentioned, I recommend using text files for config and items, yet :smiley: ).

I recommend to use 2.5.0M2 release version.

bundle:uninstall org.openhab.binding.ihc

Remove previous jar file from addons folder

bundle:install https://repo1.maven.org/maven2/org/apache/httpcomponents/httpclient-osgi/4.5.8/httpclient-osgi-4.5.8.jar
bundle:install https://repo1.maven.org/maven2/org/apache/httpcomponents/httpcore-osgi/4.4.11/httpcore-osgi-4.4.11.jar
bundle:install https://openhab.jfrog.io/openhab/online-repo-milestone/2.5/org/openhab/addons/bundles/org.openhab.binding.ihc/2.5.0.M2/org.openhab.binding.ihc-2.5.0.M2.jar

Or just download jar files from links above and put in the addons folder.

When I install the M2 version, I get this error:

019-08-13 18:26:46.968 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.ihc-2.5.0.M2.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.ihc [253]
  Unresolved requirement: Import-Package: org.apache.http; version="[4.4.0,5.0.0)"
	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

Ok, Apache http client is not anymore included to ihc binding jar, so those need to be installed manually.

bundle:install https://repo1.maven.org/maven2/org/apache/httpcomponents/httpclient-osgi/4.5.8/httpclient-osgi-4.5.8.jar
bundle:install https://repo1.maven.org/maven2/org/apache/httpcomponents/httpcore-osgi/4.4.11/httpcore-osgi-4.4.11.jar

Seems to be working fine…
Any changes, or anything special to test?

Hmm, I just noticed…
After I installed the Apache http client, the Velux binding I´m using returns a warning and fail to operate.

2019-08-13 19:06:34.051 [WARN ] [.velux.bridge.slip.SCgetDeviceStatus] - Gateway response GW_SESSION_FINISHED_NTF (772) cannot be handled at this point of interaction.
2019-08-13 19:06:34.054 [INFO ] [.velux.handler.VeluxBridgeHandlerOH1] - handleCommandOnChannel(): updating of item V_STATUS (type BRIDGE_STATUS) failed.

Guess I need to ask Guenther.

I have the same issue but using the old IHC binding. It seems to me that something is causing a reboot of the IHC controller. When I see those messages in the OpenHAB log and I go in and check the uptime of the controller, it has rebooted recently. This explains why it seems to be offline for a minute or so. Or is this different behavior from what you are all seeing?