ERROR: Harmony-Binding

Felix_Losch · April 18, 2017, 11:19am

To clarify things: I installed the latest OH2 snapshot 2.1.0 from 2017-04-17. The error can be reproduced as follows:

Harmony Hub up and running
Start OH2
Everything is OK: OH2 finds HarmonyHub and can control it
Reset Harmony Hub (switch off and on again)
OH2 produces heartbeat failed and connection errors
This error messages stay on (until you restart OH2). I thought that the binding should be able to reconnect to Harmony Hub again after heartbeat failed messages (at least if I look at the code this should be the behvaiour)

@Dan Cunningham: Could you please investigate this issue. This is very annoying (the reset of HarmonyHub) and reconnection worked with OH 2.0.0 (official release).

LuFriFri · April 18, 2017, 5:21pm

Just an update from my side:
Today I got my new harmony hub and it seems that my connection problems have gone

Sar6e · April 18, 2017, 10:59pm

I am also running the 2.1.0.SNAPSHOT version of the Harmony Hub binding. The errors I am seeing every 60 seconds appear to be the same as @Celaeno1 and @Felix_Losch

2017-04-19 08:51:34.227 [WARN ] [oftware.smack.AbstractXMPPConnection] - Connection XMPPTCPConnection[not-authenticated] (7981) closed with error
java.io.EOFException: no more data available - expected end tag </stream:stream> to close start tag <stream:stream> from line 1, parser stopped on END_TAG seen ...</mechanisms></stream:features>... @1:304
	at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3035)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.xmlpull.mxp1.MXParser.more(MXParser.java:3046)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1228)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:980)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:996)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-04-19 08:51:34.267 [ERROR] [harmonyhub.handler.HarmonyHubHandler] - Could not connect to HarmonyHub at xxx.xxx.xxx.xxx
java.lang.RuntimeException: Failed communicating with Harmony Hub
	at net.whistlingfish.harmony.HarmonyClient.connect(HarmonyClient.java:200)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at net.whistlingfish.harmony.HarmonyClient.connect(HarmonyClient.java:115)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.openhab.binding.harmonyhub.handler.HarmonyHubHandler.connect(HarmonyHubHandler.java:207)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.openhab.binding.harmonyhub.handler.HarmonyHubHandler.access$4(HarmonyHubHandler.java:178)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.openhab.binding.harmonyhub.handler.HarmonyHubHandler$3.run(HarmonyHubHandler.java:249)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Caused by: java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2067)[:1.8.0_121]
	at org.jivesoftware.smack.SynchronizationPoint.waitForConditionOrTimeout(SynchronizationPoint.java:243)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.jivesoftware.smack.SynchronizationPoint.checkIfSuccessOrWait(SynchronizationPoint.java:151)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.jivesoftware.smack.SynchronizationPoint.checkIfSuccessOrWaitOrThrow(SynchronizationPoint.java:126)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at org.jivesoftware.smack.AbstractXMPPConnection.connect(AbstractXMPPConnection.java:380)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	at net.whistlingfish.harmony.HarmonyClient.connect(HarmonyClient.java:126)[193:org.openhab.binding.harmonyhub:2.1.0.201703310852]
	... 11 more

My initial thoughts that changing the heartbeat interval were incorrect. It seems any manual intervention to contact the Harmony Hub brings it online again - like editing the heartbeat interval. But it does not stay online for long,

Celaeno1 · April 19, 2017, 6:18am

I can confirm this behavior!

At the moment my binding is running! (more than 36 hours, since last boot up!)

Here are my steps:

Complete new installation of OH2 with Snapshot 2.1.0.201703310852.

Once the HarmonyHub was detected automatically and configured, shutdown of OH2.

Rebooted HarmonyHub.

Rebooted my complete operating system (Win10, 32-bit).

Starting OH2 again.

HarmonyHub is running since 36 hours. Hopefully it will last on…

Felix_Losch · April 19, 2017, 12:21pm

The problem is not about a stable connection. When both devices,i.e. OH2 and HarmonyHub are up and running, everything works stable.

I am switching off my Harmony Hub at night. In the morning it is switched on again. After that OH2 cannot reconnect to the HarmonyHub unless I restart OH2. This still worked in OH 2.0.0 so I am wondering what has been changed between 2.0.0 and 2.1.0-SNAPSHOT.

digitaldan · April 19, 2017, 2:33pm

Let me take a look

I am wondering what has been changed between 2.0.0 and 2.1.0-SNAPSHOT.

Quite a bit actually, see Pull requests · openhab/openhab2-addons · GitHub , there was a fairly major refactor of the underlying connection library recently to be compatible with the XMPP library (SMACK) that we are using.

Celaeno1 · April 19, 2017, 2:56pm

Indeed, a lot of changes:

Felix_Losch1 · April 19, 2017, 5:49pm

I have read through all the changes. But it still does not solve the issue
of broken reconnect after you disconnect a hub from the network. Could you
please investigate this issue?

digitaldan · April 22, 2017, 6:19pm

As I mentioned, I will take a look, we had a large refactoring of the base libraries which has probably caused an issue when we need to reconnect.

wborn · April 23, 2017, 5:50pm

@digitaldan
I just had a look at the reconnect issue. It seems to be caused by the fact that the retryJob in HarmonyHubHandler cancels its own execution in disconnectFromHub() on line 230. When I comment that line the InterruptedException no longer occurs.

When the connection is setup Smack waits for a reply from the hub for 5s using awaitNanos. That method also aborts when the current thread has been interrupted due to cancellation:

     * @throws InterruptedException if the current thread is interrupted
     *         (and interruption of thread suspension is supported)
     */
    long awaitNanos(long nanosTimeout) throws InterruptedException;

I’ll wait and see if you agree and have a nice solution for this.

digitaldan · April 24, 2017, 3:50pm

@wborn thanks! I was just starting to look, that sounds reasonable, let me take a peek and see what I can do.

wborn · April 24, 2017, 9:06pm

@digitaldan’s PR #2201 with the reconnection fix just got merged and is available in 2.1.0-SNAPSHOT build #893 or newer.

I’ve also uploaded a org.openhab.binding.harmonyhub-2.1.0-SNAPSHOT.jar with this fix.

Sar6e · April 26, 2017, 6:42am

It’s great to have a fix for the Harmony Hub problem. to update to this version of the binding I can simply replace the .jar file in the relevant binding folder with the new version? Or am I better placed to uninstall and reinstall the binding?

TIA

wborn · April 26, 2017, 7:47am

The best way to upgrade depends on what kind of installation you have:

If you already have a org.openhab.binding.harmonyhub-2.1.0-SNAPSHOT.jar in your /addons directory you can simply replace that one.
When you have a OH 2.1.0-SNAPSHOT installation and use the online repository, uninstalling and reinstalling the Harmony Binding should upgrade it.

After updating, the command:

bundle:list|grep Harmony

should show a version from April 24th or newer, e.g. 2.1.0.201704251551 when using the online repository. Versions prior to April 24th will have one of the known issues listed above.

Felix_Losch · April 26, 2017, 3:03pm

Thanks so much for the fix! It works now like a charm.

martiniman · April 26, 2017, 4:53pm

Hi. I try to update harmony binding as @wborn sudgestion, but after uninstall/install i got old version.
I used paper ui and snapshot build.
What should i do to update binding?

Felix_Losch · April 26, 2017, 5:27pm

This was also the case for me. After switching “Use online repositories” to OFF in Paper UI it took the binding from the openhab2-addons KAR file. Make sure that you have the correct version installed under /usr/share/openhab2/addons

Celaeno1 · April 26, 2017, 10:34pm

Had the same problem. It always took the old version again.

At the end I just copied org.openhab.binding.harmonyhub-2.1.0-SNAPSHOT.jar into addons folder…

Now I have version: 2.1.0.201704261428

At the moment harmony binding is running, but I’m going to observe it…

Edit: After more than 1 week, continously running, no errors anymore. Good job!

NCO · April 28, 2017, 1:28pm

I had the same issue with my hub.
(it was disconnected after I re-installed my km200 binding - don’t know, if this matters though.)

However, I assume that changing the heartbeat interval in general triggers something in the binding (re-initialization or something) which leads to a re-connection!?
I have set it to 120 sec and it started working right away.

So is this a known issue maybe?
EDIT: Of course it is - and it’s fixed obviously (see above
Will check out the latest snapshot

Sar6e · May 8, 2017, 1:36am

Me too. I’m now running 2.1.0.201704261428 and the connection to the Harmony Hub is working well again. Big thanks to the maintainers! Much appreciated.