I have problems with my ihc binding, it loses connection to the controller and then connects again many times a day
My items looks like this, and i have about 80 items connected to the controler
Number Temperature_Kontor "Rum Temperatur [%.1f °C]" <temperature> (Temperatur, Kontor) ["CurrentTemperature"] {ihc="0x9d4a14", autoupdate="false"}
Controler info:
HW2
Firmware 2.8.4
2018-05-30 21:10:26.118 [ERROR] [org.openhab.binding.ihc.ws.IhcClient] - New controller state change notification wait failed...
org.openhab.binding.ihc.ws.IhcExecption: java.io.InterruptedIOException: Connection has been shut down
at org.openhab.binding.ihc.ws.IhcHttpsClient.sendQuery(IhcHttpsClient.java:103) [237:org.openhab.binding.ihc:1.11.0]
at org.openhab.binding.ihc.ws.IhcControllerService.waitStateChangeNotifications(IhcControllerService.java:164) [237:org.openhab.binding.ihc:1.11.0]
at org.openhab.binding.ihc.ws.IhcClient.waitStateChangeNotifications(IhcClient.java:347) [237:org.openhab.binding.ihc:1.11.0]
at org.openhab.binding.ihc.ws.IhcClient.access$4(IhcClient.java:343) [237:org.openhab.binding.ihc:1.11.0]
at org.openhab.binding.ihc.ws.IhcClient$IhcControllerStateListener.run(IhcClient.java:564) [237:org.openhab.binding.ihc:1.11.0]
Caused by: java.io.InterruptedIOException: Connection has been shut down
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:344) ~[?:?]
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) ~[?:?]
... 4 more
Caused by: org.apache.http.impl.conn.ConnectionShutdownException
at org.apache.http.impl.conn.CPoolProxy.getValidConnection(CPoolProxy.java:79) ~[?:?]
at org.apache.http.impl.conn.CPoolProxy.getSSLSession(CPoolProxy.java:147) ~[?:?]
at org.apache.http.impl.client.DefaultUserTokenHandler.getUserToken(DefaultUserTokenHandler.java:81) ~[?:?]
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:327) ~[?:?]
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) ~[?:?]
... 4 more
2018-05-30 21:10:26.211 [WARN ] [nhab.binding.ihc.internal.IhcBinding] - Error occurred on communication to IHC controller: java.io.InterruptedIOException: Connection has been shut down
2018-05-30 21:10:26.845 [INFO ] [nhab.binding.ihc.internal.IhcBinding] - Connecting to IHC / ELKO LS controller [IP='192.168.0.20' Username='mads' Password='******'].
For some reason which I have no idea of, I´m starting to get a problem with the IHC binding. It has been running fine for several months, and then the last coupple of weeks, it no longer do…
The symptom is very strange when it happesn…
Controller is online just fine. But I receive nothing from the controller, and cant control anything either.
Restarting the binding solves the problem. But after some days days, it happens again.
I´m using openhab 2.5.0 and the IHC binding 2.5.0 as well…
I just look in the openhab.log file… The last state received from the controller this morning was 08.55. And there is nothing in the log afterwards which indicate any problems with IHC binding. I normally would receive alot of states, cause I´m using IHC pir´s which is added to openhab. And since we´re working home, alot of motion is going on all the time
After I restarted the bundle about 11:30 it started to receive updates again, and control is beeing send to the controller as well.
Do you have any idea why this may happen or what I can do?
Since this happens very rare I wonder if debug logging would make any good.
Without debug/trace level logs it’s rather difficult to say anything. Next time when problem occurs, you could change ihc binding log level to trace (without restart) to see if that give any hint about the issue.
I am so glad someone else is experiencing this! It is so hard to pinpoint or recreate. I will turn on TRACE when it happens again. I had it running in DEBUG now and this is also being thrown I suppose every minute
2020-05-18 21:47:34.610 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - Update RF device data
2020-05-18 21:47:34.740 [DEBUG] [ding.ihc.internal.handler.IhcHandler] - Error occured when fetching RF device information, reason: : Error occured during XML data parsing
org.openhab.binding.ihc.internal.ws.exeptions.IhcExecption: Error occured during XML data parsing
at org.openhab.binding.ihc.internal.ws.services.IhcAirlinkManagementService.getDetectedDeviceList(IhcAirlinkManagementService.java:67) ~[?:?]
at org.openhab.binding.ihc.internal.ws.IhcClient.getDetectedRFDevices(IhcClient.java:262) ~[?:?]
at org.openhab.binding.ihc.internal.handler.IhcHandler.updateRfDeviceStates(IhcHandler.java:845) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: java.lang.NumberFormatException: For input string: ""
at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:1.8.0_222]
at java.lang.Integer.parseInt(Integer.java:592) ~[?:1.8.0_222]
at java.lang.Integer.parseInt(Integer.java:615) ~[?:1.8.0_222]
at org.openhab.binding.ihc.internal.ws.services.IhcAirlinkManagementService.parseResourceValue(IhcAirlinkManagementService.java:78) ~[?:?]
at org.openhab.binding.ihc.internal.ws.services.IhcAirlinkManagementService.getDetectedDeviceList(IhcAirlinkManagementService.java:57) ~[?:?]
... 9 more
Issue doesn’t cause any harm, but just print out error in debug level. Could you enable trace level logs and post soap message here, so that I can see what control response when there is no rf devices at all (i will not remove my rf devices just to test this). I will then try to fixit and also add junit test for it.
