Openhab-addons: [harmonyhub] Exceptions when turning off hub

Created on 30 Jul 2018  路  27Comments  路  Source: openhab/openhab-addons

My harmony hub is connected to a power outlet strip together with the AV-Receiver and the TV.
When I turn off the devices I get exceptions from the harmony binding:

2018-07-30 08:54:50.760 [WARN ] [.whistlingfish.harmony.HarmonyClient] - Send heartbeat failed
java.lang.RuntimeException: Failed communicating with Harmony Hub
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:342) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:331) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at net.whistlingfish.harmony.HarmonyClient.sendPing(HarmonyClient.java:400) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at net.whistlingfish.harmony.HarmonyClient$2.run(HarmonyClient.java:181) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        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.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 5000ms (~5s). Waited for response using: net.whistlingfish.harmony.protocol.OAReplyFilter@86f543.
        at org.jivesoftware.smack.SmackException$NoResponseException.newWith(SmackException.java:110) ~[?:?]
        at org.jivesoftware.smack.SmackException$NoResponseException.newWith(SmackException.java:97) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.getNextStanzaSkipContinues(HarmonyClient.java:354) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:340) ~[?:?]
        ... 10 more
2018-07-30 08:55:20.766 [WARN ] [harmonyhub.handler.HarmonyHubHandler] - heartbeat failed
java.lang.RuntimeException: Failed communicating with Harmony Hub
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:342) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:331) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.sendPing(HarmonyClient.java:400) ~[?:?]
        at org.openhab.binding.harmonyhub.handler.HarmonyHubHandler.lambda$0(HarmonyHubHandler.java:240) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        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.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 5000ms (~5s). Waited for response using: net.whistlingfish.harmony.protocol.OAReplyFilter@113f323.
        at org.jivesoftware.smack.SmackException$NoResponseException.newWith(SmackException.java:110) ~[?:?]
        at org.jivesoftware.smack.SmackException$NoResponseException.newWith(SmackException.java:97) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.getNextStanzaSkipContinues(HarmonyClient.java:354) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:340) ~[?:?]
        ... 10 more
2018-07-30 08:55:50.766 [WARN ] [.whistlingfish.harmony.HarmonyClient] - Send heartbeat failed
java.lang.RuntimeException: Failed communicating with Harmony Hub
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:342) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:331) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at net.whistlingfish.harmony.HarmonyClient.sendPing(HarmonyClient.java:400) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at net.whistlingfish.harmony.HarmonyClient$2.run(HarmonyClient.java:181) [189:org.openhab.binding.harmonyhub:2.4.0.201807281702]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        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.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 5000ms (~5s). Waited for response using: net.whistlingfish.harmony.protocol.OAReplyFilter@1bffab2.
        at org.jivesoftware.smack.SmackException$NoResponseException.newWith(SmackException.java:110) ~[?:?]
        at org.jivesoftware.smack.SmackException$NoResponseException.newWith(SmackException.java:97) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.getNextStanzaSkipContinues(HarmonyClient.java:354) ~[?:?]
        at net.whistlingfish.harmony.HarmonyClient.sendOAStanza(HarmonyClient.java:340) ~[?:?]
        ... 10 more
picture NorbertHD

All 27 comments

Same here

iandronowicz picture iandronowicz on 20 Sep 2018

It throws another exception when disconnecting power from a Hub now that the binding switched from XMPP to the Websocket protocol (#4926):

19:21:58.880 [ERROR] [com.digitaldan.harmony.HarmonyClient ] - onWebSocketError
org.eclipse.jetty.io.EofException: null
    at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:286) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:429) ~[75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:323) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.FrameFlusher.flush(FrameFlusher.java:218) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.FrameFlusher.process(FrameFlusher.java:157) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:90) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:495) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.client.io.WebSocketClientConnection.outgoingFrame(WebSocketClientConnection.java:72) [91:org.eclipse.jetty.websocket.client:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.WebSocketSession.close(WebSocketSession.java:223) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.WebSocketSession.close(WebSocketSession.java:202) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onConnectionStateChange(AbstractWebSocketConnection.java:353) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.IOState.notifyStateListeners(IOState.java:184) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.IOState.onReadFailure(IOState.java:498) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:547) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:391) [92:org.eclipse.jetty.websocket.common:9.4.11.v20180605]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.IOException: Broken pipe
    at sun.nio.ch.FileDispatcherImpl.writev0(Native Method) ~[?:?]
    at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51) ~[?:?]
    at sun.nio.ch.IOUtil.write(IOUtil.java:148) ~[?:?]
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) ~[?:?]
    at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:266) ~[?:?]
    ... 23 more

Also the Thing status isn't immediately updated to offline. Perhaps the onWebSocketError handling can be improved a bit @digitaldan?

wborn picture wborn on 23 Feb 2019

Yep, I was just looking at the fact I am not handling those well, look for a PR soon

digitaldan picture digitaldan on 23 Feb 2019
👍1

Getting still the same error with snapshot: 2.5.0.201902252032

2019-02-27 17:53:30.369 [ERROR] [com.digitaldan.harmony.HarmonyClient] - onWebSocketError
org.eclipse.jetty.io.EofException: null
    at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:286) ~[77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393) ~[77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277) [77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380) [77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.FrameFlusher.flush(FrameFlusher.java:218) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.FrameFlusher.process(FrameFlusher.java:157) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:90) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:495) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.client.io.WebSocketClientConnection.outgoingFrame(WebSocketClientConnection.java:72) [93:org.eclipse.jetty.websocket.client:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.WebSocketSession.close(WebSocketSession.java:223) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.WebSocketSession.close(WebSocketSession.java:202) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onConnectionStateChange(AbstractWebSocketConnection.java:353) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.IOState.notifyStateListeners(IOState.java:184) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.IOState.onReadFailure(IOState.java:498) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:547) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:391) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [77:org.eclipse.jetty.io:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) [89:org.eclipse.jetty.util:9.4.12.v20180830]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
    at sun.nio.ch.SocketDispatcher.writev0(Native Method) ~[?:?]
    at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:55) ~[?:?]
    at sun.nio.ch.IOUtil.write(IOUtil.java:148) ~[?:?]
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) ~[?:?]
    at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:266) ~[?:?]
    ... 28 more
Celaeno1 picture Celaeno1 on 27 Feb 2019

@Celaeno1 @digitaldan fixed this in https://github.com/digitaldan/harmony-client/commit/25a7cdb86cee25e1535cb5772a960d5908ff5577 .
But this fix is not in the harmony-client-1.1.1.jar in the current org.openhab.binding.harmonyhub-2.5.0-SNAPSHOT.jar.

NorbertHD picture NorbertHD on 27 Feb 2019
❤1

I cannot reopen this issue because @wborn closed it.

NorbertHD picture NorbertHD on 27 Feb 2019

That error message would indicate it is using the older version, I will check when I am back in town on Friday and can test

digitaldan picture digitaldan on 27 Feb 2019
👍1

Before I open another PR, can someone my new version of this ?

https://github.com/digitaldan/openhab2-addons/releases/download/harmony-websocket-1.1/org.openhab.binding.harmonyhub-2.5.0-SNAPSHOT.jar

digitaldan picture digitaldan on 28 Feb 2019

@digitaldan Thanks for the quick response! 馃憤 Ok, inside this new snapshot above, there is a new harmony-client-1.1.2.jar. I'm going to test new snapshot this evening, because I'm at work at the moment...!

Celaeno1 picture Celaeno1 on 28 Feb 2019

@digitaldan

I did some testing with new snapshot. No errors in openhab.log BUT errors in event.log:

COMMUNICATION_ERROR from time to time!

2019-02-28 18:11:27.490 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null
2019-02-28 18:11:27.496 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:11:27.498 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:11:27.501 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:11:27.504 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:11:27.507 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:11:27.510 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-02-28 18:12:27.707 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE
2019-02-28 18:12:27.724 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:12:27.729 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:12:27.749 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:12:27.753 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:12:27.756 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:12:27.760 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:12:27.764 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-02-28 18:12:27.890 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-02-28 18:12:27.989 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-02-28 18:12:28.085 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-02-28 18:12:28.183 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-02-28 18:12:28.279 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.
2019-02-28 18:12:28.284 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.

2019-02-28 18:21:08.931 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:08.938 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PLAY to PAUSE
2019-02-28 18:21:10.962 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:11.692 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:12.176 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:12.547 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:12.728 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:12.944 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:21:13.069 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE

2019-02-28 18:21:30.111 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff

2019-02-28 18:21:30.117 [WARN ] [b.internal.handler.HarmonyHubHandler] - Cannot send command 'PowerOff' on harmonyhub:hub:HarmonyHub:currentActivity because HarmonyClient is not connected

2019-02-28 18:21:30.123 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from CD abspielen to PowerOff

2019-02-28 18:21:31.932 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null
2019-02-28 18:21:31.938 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:21:31.941 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:21:31.945 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:21:31.948 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:21:31.951 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:21:31.953 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-02-28 18:22:32.210 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE
2019-02-28 18:22:32.221 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:22:32.223 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:22:32.228 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:22:32.230 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:22:32.235 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:22:32.238 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:22:32.241 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-02-28 18:22:32.243 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to CD abspielen
2019-02-28 18:22:32.319 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-02-28 18:22:32.424 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-02-28 18:22:32.532 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-02-28 18:22:32.536 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.
2019-02-28 18:22:32.628 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-02-28 18:22:32.724 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.

2019-02-28 18:23:06.175 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:23:09.894 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:23:09.900 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PAUSE to PLAY

2019-02-28 18:23:30.359 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command NEXT

2019-02-28 18:25:23.271 [ome.event.ItemCommandEvent] - Item 'HarmonyButtonPress' received command Stop

2019-02-28 18:25:38.578 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY

2019-02-28 18:26:36.390 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null
2019-02-28 18:26:36.393 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:26:36.396 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:26:36.398 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:26:36.401 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:26:36.404 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:26:36.407 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-02-28 18:27:36.623 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE
2019-02-28 18:27:36.635 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:27:36.639 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:27:36.647 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:27:36.650 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:27:36.655 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:27:36.660 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:27:36.664 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-02-28 18:27:36.748 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-02-28 18:27:36.848 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-02-28 18:27:36.948 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-02-28 18:27:36.952 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-02-28 18:27:37.049 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-02-28 18:27:37.188 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.

2019-02-28 18:31:10.327 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command NEXT
2019-02-28 18:34:46.716 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:34:46.723 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PLAY to PAUSE
2019-02-28 18:34:58.489 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:34:58.497 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PAUSE to PLAY
2019-02-28 18:35:44.037 [ome.event.ItemCommandEvent] - Item 'HarmonyButtonPress' received command Stop
2019-02-28 18:35:47.215 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY

2019-02-28 18:35:58.156 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:35:58.176 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from CD abspielen to PowerOff
2019-02-28 18:35:58.453 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff


2019-02-28 18:36:30.548 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command Internetradio

2019-02-28 18:36:30.555 [WARN ] [b.internal.handler.HarmonyHubHandler] - Cannot send command 'Internetradio' on harmonyhub:hub:HarmonyHub:currentActivity because HarmonyClient is not connected

2019-02-28 18:36:30.562 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to Internetradio
2019-02-28 18:36:40.815 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null
2019-02-28 18:36:40.820 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:36:40.823 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:36:40.827 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:36:40.830 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:36:40.835 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:36:40.839 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-02-28 18:37:41.044 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE
2019-02-28 18:37:41.055 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:37:41.059 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:37:41.065 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:37:41.070 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:37:41.074 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-02-28 18:37:41.078 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:37:41.083 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2019-02-28 18:37:41.087 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from Internetradio to CD abspielen

2019-02-28 18:37:41.177 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-02-28 18:37:41.282 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-02-28 18:37:41.286 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-02-28 18:37:41.389 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-02-28 18:37:41.392 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-02-28 18:37:41.530 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.

2019-02-28 18:38:04.368 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:38:04.384 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from CD abspielen to PowerOff

2019-02-28 18:38:31.455 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command Internetradio
2019-02-28 18:38:31.474 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to Internetradio
2019-02-28 18:38:31.769 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered Internetradio
2019-02-28 18:39:03.017 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered Internetradio

2019-02-28 18:40:05.121 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:40:05.131 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from Internetradio to PowerOff
2019-02-28 18:40:05.429 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-02-28 18:40:05.809 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff

2019-02-28 18:40:40.894 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command CD abspielen
2019-02-28 18:40:40.909 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to CD abspielen
2019-02-28 18:40:41.220 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered CD_abspielen
2019-02-28 18:40:48.258 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered CD_abspielen

2019-02-28 18:41:13.009 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:41:13.030 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from CD abspielen to PowerOff
2019-02-28 18:41:13.327 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-02-28 18:41:14.815 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff

2019-02-28 18:41:34.600 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: Disconnected
2019-02-28 18:41:34.605 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:41:34.609 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:41:34.612 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:41:34.618 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-02-28 18:41:34.628 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:41:34.634 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: Disconnected to UNKNOWN
2019-02-28 18:41:34.638 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:41:34.641 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 18:41:34.921 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from UNKNOWN to ONLINE
2019-02-28 18:41:34.927 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:41:34.933 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:41:34.936 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:41:34.939 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:41:34.942 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:41:34.944 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 18:41:35.048 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-02-28 18:41:35.054 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-02-28 18:41:35.200 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-02-28 18:41:35.204 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-02-28 18:41:35.305 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-02-28 18:41:35.313 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-02-28 18:41:35.415 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.

2019-02-28 18:42:04.636 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command Internetradio
2019-02-28 18:42:04.653 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to Internetradio
2019-02-28 18:42:04.926 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered Internetradio
2019-02-28 18:42:36.156 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered Internetradio

2019-02-28 18:43:49.448 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:43:49.460 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from Internetradio to PowerOff
2019-02-28 18:43:49.766 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-02-28 18:43:50.146 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff

2019-02-28 18:44:10.915 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command CD abspielen
2019-02-28 18:44:10.932 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to CD abspielen
2019-02-28 18:44:11.359 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered CD_abspielen
2019-02-28 18:44:18.372 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered CD_abspielen

2019-02-28 18:44:45.982 [ome.event.ItemCommandEvent] - Item 'HarmonyButtonPress' received command Stop
2019-02-28 18:44:55.562 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:45:14.258 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command NEXT
2019-02-28 18:46:23.870 [ome.event.ItemCommandEvent] - Item 'HarmonyButtonPress' received command Stop
2019-02-28 18:46:32.517 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY

2019-02-28 18:47:06.915 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:47:06.934 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from CD abspielen to PowerOff
2019-02-28 18:47:07.234 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-02-28 18:47:08.731 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff

2019-02-28 18:48:01.650 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command Internetradio
2019-02-28 18:48:01.675 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to Internetradio
2019-02-28 18:48:01.955 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered Internetradio
2019-02-28 18:48:33.195 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered Internetradio

2019-02-28 18:49:05.994 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:49:06.011 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from Internetradio to PowerOff
2019-02-28 18:49:06.304 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-02-28 18:49:06.683 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff

2019-02-28 18:49:38.578 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command CD abspielen
2019-02-28 18:49:38.595 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to CD abspielen
2019-02-28 18:49:38.890 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered CD_abspielen
2019-02-28 18:49:45.922 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered CD_abspielen

2019-02-28 18:50:09.022 [ome.event.ItemCommandEvent] - Item 'HarmonyButtonPress' received command Stop
2019-02-28 18:50:10.878 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:50:13.315 [ome.event.ItemCommandEvent] - Item 'HarmonyButtonPress' received command Stop
2019-02-28 18:50:14.839 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:50:14.846 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PLAY to PAUSE
2019-02-28 18:50:15.980 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:50:15.988 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PAUSE to PLAY
2019-02-28 18:50:19.046 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:50:21.099 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command NEXT
2019-02-28 18:50:47.562 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PAUSE
2019-02-28 18:50:47.570 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PLAY to PAUSE
2019-02-28 18:50:49.847 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PLAY
2019-02-28 18:50:49.857 [vent.ItemStateChangedEvent] - HarmonyPlayer changed from PAUSE to PLAY

2019-02-28 18:50:52.053 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PREVIOUS
2019-02-28 18:50:53.136 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PREVIOUS
2019-02-28 18:50:57.565 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PREVIOUS
2019-02-28 18:50:57.936 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PREVIOUS
2019-02-28 18:51:02.328 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PREVIOUS
2019-02-28 18:51:02.544 [ome.event.ItemCommandEvent] - Item 'HarmonyPlayer' received command PREVIOUS

2019-02-28 18:51:17.482 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-02-28 18:51:17.491 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from CD abspielen to PowerOff
2019-02-28 18:51:17.793 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-02-28 18:51:19.291 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff

2019-02-28 19:07:09.426 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null
2019-02-28 19:07:09.430 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 19:07:09.432 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 19:07:09.435 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 19:07:09.437 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 19:07:09.440 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-02-28 19:07:09.443 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-02-28 19:08:09.658 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE
2019-02-28 19:08:09.669 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 19:08:09.672 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 19:08:09.676 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 19:08:09.679 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 19:08:09.688 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 19:08:09.690 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-02-28 19:08:09.692 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-02-28 19:08:09.777 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-02-28 19:08:09.781 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-02-28 19:08:09.922 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-02-28 19:08:10.022 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-02-28 19:08:10.120 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-02-28 19:08:10.214 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.
Celaeno1 picture Celaeno1 on 28 Feb 2019

Can you turn logging up in the console foe the client library?

log:set DEBUG com.digitaldan.harmony

digitaldan picture digitaldan on 28 Feb 2019

@digitaldan

Ok. I've set it to DEBUG now. Let's wait a while...

Celaeno1 picture Celaeno1 on 28 Feb 2019

@digitaldan
It took long, but the error came!

See here:

2019-03-01 00:00:10.926 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"72ab8d61-6acb-46bc-badd-59a222a3b714","params":{}}}
2019-03-01 00:01:00.930 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"55cce039-22d9-4282-9c9e-12c4ffba8cd9","params":{}}}
2019-03-01 00:01:50.935 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"244177b9-ed43-423c-91ba-8f75e0348c05","params":{}}}

2019-03-01 00:02:05.259 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketClose 1006 Disconnected
2019-03-01 00:02:05.261 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose Disconnected {}

2019-03-01 00:02:05.265 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: Disconnected
2019-03-01 00:02:05.272 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-03-01 00:02:05.275 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-03-01 00:02:05.278 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: Disconnected to UNKNOWN
2019-03-01 00:02:05.282 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-03-01 00:02:05.285 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-03-01 00:02:05.288 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-03-01 00:02:05.291 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2019-03-01 00:02:05.294 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-03-01 00:02:05.551 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketConnect WebSocketSession[websocket=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],behavior=CLIENT,connection=WebSocketClientConnection@15306c8c::SocketChannelEndPoint@3435ae{/192.168.178.20:8088<->/192.168.178.24:55017,OPEN,fill=-,flush=-,to=5/300000}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@15306c8c[ios=IOState@136b3cc[CONNECTED,!in,out],f=Flusher@1a4271a[queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@79f758[ExtensionStack,s=START,c=0,len=0,f=null]],remote=WebSocketRemoteEndpoint@1013d3c[batching=true],incoming=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],outgoing=ExtensionStack[queueSize=0,extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]]

2019-03-01 00:02:05.563 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41678312' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-03-01 00:02:05.565 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from UNKNOWN to ONLINE
2019-03-01 00:02:05.570 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588244' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-03-01 00:02:05.574 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588246' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-03-01 00:02:05.576 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41594344' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-03-01 00:02:05.579 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41717163' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-03-01 00:02:05.581 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:41588245' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-03-01 00:02:05.705 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588244' has been updated.
2019-03-01 00:02:05.711 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.
2019-03-01 00:02:05.816 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41717163' has been updated.
2019-03-01 00:02:05.823 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41678312' has been updated.
2019-03-01 00:02:05.918 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41594344' has been updated.
2019-03-01 00:02:06.015 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588246' has been updated.
2019-03-01 00:02:06.017 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:41588245' has been updated.


2019-03-01 00:02:27.313 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command Internetradio
2019-03-01 00:02:27.321 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"harmony.activityengine?runactivity","id":"98f28e88-41b3-41a7-b679-95fd2de182d1","params":{"timeStamp":21765,"args":{"rule":"start"},"activityId":"24066331"}}}
2019-03-01 00:02:27.331 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from PowerOff to Internetradio
2019-03-01 00:02:27.610 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - status listener[org.openhab.binding.harmonyhub.internal.handler.HarmonyHubHandler@174c043] notified: Activity[24066331]:Internetradio - ACTIVITY_IS_STARTING
2019-03-01 00:02:27.613 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered Internetradio
2019-03-01 00:02:27.958 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "harmony.engine?startActivity"

2019-03-01 00:02:34.597 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "harmony.engine?startActivity"

2019-03-01 00:02:35.557 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"0b394919-aab7-4a69-9d5d-d5724f82b022","params":{}}}

2019-03-01 00:02:38.084 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:02:38.101 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"

2019-03-01 00:02:58.867 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - status listener[org.openhab.binding.harmonyhub.internal.handler.HarmonyHubHandler@174c043] notified: Activity[24066331]:Internetradio - ACTIVITY_IS_STARTED
2019-03-01 00:02:58.870 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered Internetradio
2019-03-01 00:02:58.883 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - ActivityFinishedMessage 24066331

2019-03-01 00:03:05.561 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"19a4771b-52f2-4cfd-81c9-c64538e2431a","params":{}}}
2019-03-01 00:03:08.504 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:08.534 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:18.674 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:18.710 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:35.565 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"ea9f804c-882a-4cc9-8d70-3692cc505b41","params":{}}}
2019-03-01 00:03:38.939 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:38.966 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:59.215 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:03:59.242 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"

2019-03-01 00:04:00.062 [ome.event.ItemCommandEvent] - Item 'HarmonyActivityCurr' received command PowerOff
2019-03-01 00:04:00.071 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"harmony.activityengine?runactivity","id":"a9b9eeee-bdda-44ab-863d-047ce977afe2","params":{"timeStamp":114516,"args":{"rule":"start"},"activityId":"-1"}}}
2019-03-01 00:04:00.091 [vent.ItemStateChangedEvent] - HarmonyActivityCurr changed from Internetradio to PowerOff
2019-03-01 00:04:00.373 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - status listener[org.openhab.binding.harmonyhub.internal.handler.HarmonyHubHandler@174c043] notified: Activity[24066331]:Internetradio - HUB_IS_TURNING_OFF
2019-03-01 00:04:00.375 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered PowerOff
2019-03-01 00:04:00.729 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "harmony.engine?startActivity"
2019-03-01 00:04:00.754 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - status listener[org.openhab.binding.harmonyhub.internal.handler.HarmonyHubHandler@174c043] notified: Activity[-1]:PowerOff - HUB_IS_OFF
2019-03-01 00:04:00.756 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered PowerOff
2019-03-01 00:04:00.778 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - ActivityFinishedMessage -1

2019-03-01 00:04:05.570 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"004d27ae-35ce-41f8-84ba-fe1369437313","params":{}}}
2019-03-01 00:04:19.496 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:04:19.523 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:04:29.657 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:04:29.684 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:04:35.574 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"dd2ad15b-ef39-4ff0-9cbd-55b1e48a708b","params":{}}}
2019-03-01 00:04:49.928 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 00:04:49.955 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
Celaeno1 picture Celaeno1 on 1 Mar 2019

@digitaldan

The most interesting part from logfile above:

2019-03-01 00:02:05.259 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketClose 1006 Disconnected

2019-03-01 00:02:05.261 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose Disconnected {}

2019-03-01 00:02:05.551 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketConnect WebSocketSession[websocket=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],behavior=CLIENT,connection=WebSocketClientConnection@15306c8c::SocketChannelEndPoint@3435ae{/192.168.178.20:8088<->/192.168.178.24:55017,OPEN,fill=-,flush=-,to=5/300000}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@15306c8c[ios=IOState@136b3cc[CONNECTED,!in,out],f=Flusher@1a4271a[queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@79f758[ExtensionStack,s=START,c=0,len=0,f=null]],remote=WebSocketRemoteEndpoint@1013d3c[batching=true],incoming=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],outgoing=ExtensionStack[queueSize=0,extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]]

Celaeno1 picture Celaeno1 on 1 Mar 2019

@Celaeno1 can you set the hub thing "heartBeatInterval" to something like 30 seconds?

digitaldan picture digitaldan on 1 Mar 2019

@digitaldan

In the beginning of my tests "heartBeatInterval" was set to 30 sec.
The "communication error" came often.

Then I've set it to 50 sec. The "communication error" came less.

I've reset it to 30 sec now. Let's see what will happen...

Celaeno1 picture Celaeno1 on 1 Mar 2019

@digitaldan

It is very weird. For 7 hours NO more (COMMUNICATION_ERROR)s in log files.

As I said before:

"heartBeatInterval" was 30 sec. --> a lot of (COMMUNICATION_ERROR)s.

Changed to 50 sec. --> less (COMMUNICATION_ERROR)s
Changed back to 30 sec. --> NO more (COMMUNICATION_ERROR)s

The only odd messages in openhab.log are:

Unknown message type "automation.state?notify"

2019-03-01 07:22:40.098 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"9ae949d1-8b50-462c-8cad-8af9d23a93f8","params":{}}}
2019-03-01 07:22:49.907 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 07:22:49.935 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 07:22:49.962 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 07:23:00.089 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 07:23:00.116 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 07:23:00.145 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 07:23:10.103 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"147b9d9c-22a7-4c03-bea0-ddea6b42f0c3","params":{}}}
Celaeno1 picture Celaeno1 on 1 Mar 2019

The harmony hub will disconnect the socket if it does not receive a ping after 60 seconds. I have the maximum you can set the hearbeat interval to as 50 seconds as it seemed a reasonable upper limit.
The default is 30, but since the XMPP version defaulted to 60 my guess is most users will have this config carry over, and hence they will be pinging at the upper limit of 50. I think i need to lower this.

It is very weird. For 7 hours NO more (COMMUNICATION_ERROR)s in log files.

I have 5 hubs and have found them to have relatively weak wifi strength, so i'm not sure if this is anything that is fixed in the binding, but rather just a period of relative network stability. Acording to the IETF specs a 1006 error (seen above) is a abnormal close of the socket:

      1006 is a reserved value and MUST NOT be set as a status code in a
      Close control frame by an endpoint.  It is designated for use in
      applications expecting a status code to indicate that the
      connection was closed abnormally, e.g., without sending or
      receiving a Close control frame.

So our underlying Jetty client is getting a EOF error , I would assume this is b/c a network issue and not the HUB sending a close event, but I would need to test that theory.

This is all a very long way of saying i might look at setting the heartbeat level lower ;-)

digitaldan picture digitaldan on 1 Mar 2019

Unknown message type "automation.state?notify"

Since the websocket protocol is not documented, we don't respond to all messages, so its safe to ignore these.

digitaldan picture digitaldan on 1 Mar 2019
👍1

@digitaldan

I have one theory: I used XMPP all the time with 60 sec. Then I've upgraded to Websocket snapshot using the same thing(!!) again. Could it be that somehow the 60 sec. were still used (e.g. due to cache or something else)? After setting it to 50 sec (=MAXIMUM), I had to SAVE the config of the thing! Then it used 50 sec. (for the first time lower than 60 sec.) After setting it to 30 sec (=DEFAULT) and SAVED it again, then uses the 30 sec. for the first time!!

Celaeno1 picture Celaeno1 on 1 Mar 2019

See https://github.com/openhab/openhab2-addons/blob/master/addons/binding/org.openhab.binding.harmonyhub/src/main/java/org/openhab/binding/harmonyhub/internal/handler/HarmonyHubHandler.java#L258

Unless that logic is wrong, there is no way we use a heartbeat larger then 50

digitaldan picture digitaldan on 1 Mar 2019

@digitaldan
OK! Then it is an other problem.

My Harmony Hub via "Elite Remote" is telling me that Wifi connection is: excellent

Today from 7:24 until now I got 9 times "COMMUNICATION ERROR" again.

And 4 times this error message:

2019-03-01 12:07:57.376 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketError
org.eclipse.jetty.io.EofException: null
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:286) ~[77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.io.WriteFlusher.flush(WriteFlusher.java:393) ~[77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.io.WriteFlusher.write(WriteFlusher.java:277) [77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.io.AbstractEndPoint.write(AbstractEndPoint.java:380) [77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.FrameFlusher.flush(FrameFlusher.java:218) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.FrameFlusher.process(FrameFlusher.java:157) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:241) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:224) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:90) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:495) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.client.io.WebSocketClientConnection.outgoingFrame(WebSocketClientConnection.java:72) [93:org.eclipse.jetty.websocket.client:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.WebSocketSession.close(WebSocketSession.java:223) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.WebSocketSession.close(WebSocketSession.java:202) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onConnectionStateChange(AbstractWebSocketConnection.java:353) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.IOState.notifyStateListeners(IOState.java:184) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.IOState.onReadFailure(IOState.java:498) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:547) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:391) [94:org.eclipse.jetty.websocket.common:9.4.12.v20180830]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [77:org.eclipse.jetty.io:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) [89:org.eclipse.jetty.util:9.4.12.v20180830]
at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.writev0(Native Method) ~[?:?]
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:55) ~[?:?]
at sun.nio.ch.IOUtil.write(IOUtil.java:148) ~[?:?]
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:504) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:266) ~[?:?]
... 28 more
2019-03-01 12:07:57.385 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose null {}

Celaeno1 picture Celaeno1 on 1 Mar 2019

Do you have debug logs of the pings before this error, I would need to see when the last couple pings

Caused by: java.io.IOException: An existing connection was forcibly closed by the remote host

Means either the hub disconnected us, or there was a network issue

digitaldan picture digitaldan on 1 Mar 2019

@digitaldan

Before error:

2019-03-01 11:48:38.029 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"1c3109c3-01cd-46f6-8146-8a5dd9c4846b","params":{}}}
2019-03-01 11:49:08.035 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"0a2e2db8-493f-4bd4-bddd-7c1018cfdfee","params":{}}}
2019-03-01 11:49:38.043 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"0bc57c05-1c40-4af6-a338-05cc1f4e4b29","params":{}}}
2019-03-01 11:50:08.049 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"3d1a82e2-51d9-468c-ad5b-10c01e115cef","params":{}}}
2019-03-01 11:50:38.054 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"42acad68-1f06-4d8d-9b62-e09e07ff0c05","params":{}}}
2019-03-01 11:51:08.059 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"58769557-eea9-425c-bcc4-03337089a192","params":{}}}
2019-03-01 11:51:38.064 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"8648e9d1-8459-463b-a152-fc63fa5edc50","params":{}}}
2019-03-01 11:52:08.069 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"03dd5406-72aa-49e5-8927-eb80935cd697","params":{}}}
2019-03-01 11:52:38.074 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"b6a1c817-5382-46ae-a5b8-e8ff626cf0ea","params":{}}}
2019-03-01 11:53:08.079 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"c9f23a0e-cae9-4d4a-87c1-dd841345e886","params":{}}}
2019-03-01 11:53:38.085 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"db43f8b6-58c7-4cfc-b3b6-ba6b38d8b0a5","params":{}}}
2019-03-01 11:54:08.090 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"5d544686-d6d0-4cff-96cf-5cf58e606efa","params":{}}}
2019-03-01 11:54:38.095 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"57988f5b-915c-45a6-a59d-124674c3c8de","params":{}}}
2019-03-01 11:55:08.099 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"2d196744-3ac8-4d97-afb5-0425b8ae2cef","params":{}}}
2019-03-01 11:55:38.105 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"57c19d8d-6fb0-4f8a-8b6f-943736054144","params":{}}}
2019-03-01 11:56:08.112 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"3c202725-7e3e-4029-ac9f-5a2170162018","params":{}}}
2019-03-01 11:56:38.118 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"c37d43a9-3a4d-4041-aa64-85db56cb80ca","params":{}}}
2019-03-01 11:57:08.124 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"b031e657-80e5-44ed-8858-5b51ee8d5af2","params":{}}}
2019-03-01 11:57:38.130 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"03da63a4-e6dc-4d96-a329-5da87196023e","params":{}}}
2019-03-01 11:58:08.136 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"8e436bad-4fc8-45f6-87ff-158cf9874228","params":{}}}
2019-03-01 11:58:38.141 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"05111fb7-6fe6-43b8-9001-0c2fb9757186","params":{}}}
2019-03-01 11:59:08.145 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"fc0d207d-b754-431c-97a1-b694b1ae213b","params":{}}}
2019-03-01 11:59:38.150 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"c50e58c7-c34a-4a2d-9286-a14a5c612b7b","params":{}}}
2019-03-01 12:00:08.154 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"a059f425-8881-42e6-b0e2-168e1270096d","params":{}}}
2019-03-01 12:00:38.159 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"60e62e81-5d13-4b57-b326-53ac900fb937","params":{}}}
2019-03-01 12:01:08.164 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"f1248ca3-6965-4ce0-99ba-52d90c3706b2","params":{}}}
2019-03-01 12:01:38.171 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"21c1c1b7-5ab5-4a0d-a402-387cd9dcb53a","params":{}}}
2019-03-01 12:02:08.175 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"f13f20a5-e4f6-4bc6-bf7d-65b4447a3ddb","params":{}}}
2019-03-01 12:02:38.180 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"46e009a7-dc72-4250-9604-8e728542a115","params":{}}}
2019-03-01 12:03:08.184 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"0f1c512d-8ef4-4fbe-b32e-7d9b58b5dc84","params":{}}}
2019-03-01 12:03:38.190 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"a4cc5837-8961-4c41-a50c-dae539005ac9","params":{}}}
2019-03-01 12:04:08.195 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"13925d0a-d88b-4785-8a93-2217a3b72022","params":{}}}
2019-03-01 12:04:38.201 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"3b4c4a6a-c8c3-4ff5-aae0-8227e809ba80","params":{}}}
2019-03-01 12:05:08.206 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"16426c90-1f4e-4fb6-9fb3-0c1c523c5109","params":{}}}
2019-03-01 12:05:38.211 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"41288e38-e848-4ba8-932e-e0fb3ee2fdd3","params":{}}}
2019-03-01 12:06:08.217 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"23929fd4-c6b1-4b08-a4ee-cc1502287a3f","params":{}}}
2019-03-01 12:06:38.221 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"617d8da2-3856-461f-af31-095b6c95c040","params":{}}}
2019-03-01 12:07:08.227 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"8133e07f-394d-4a66-9e28-bf41a0716cd2","params":{}}}
2019-03-01 12:07:38.233 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"438dab4d-9b35-4d9e-b17b-5493726a8bfe","params":{}}}
2019-03-01 12:07:38.713 [DEBUG] [harmony.messages.MessageDeserializer] - Unknown message type "automation.state?notify"
2019-03-01 12:07:57.376 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketError

After error:

2019-03-01 12:08:12.394 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketClose 1006 WebSocket Read EOF
2019-03-01 12:08:12.395 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose WebSocket Read EOF {}
2019-03-01 12:09:12.603 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketConnect WebSocketSession[websocket=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],behavior=CLIENT,connection=WebSocketClientConnection@1530d71c::SocketChannelEndPoint@1395539{/192.168.178.20:8088<->/192.168.178.24:55897,OPEN,fill=-,flush=-,to=17/300000}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@1530d71c[ios=IOState@3bc2ba[CONNECTED,!in,out],f=Flusher@4496c2[queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@1fb0c4b[ExtensionStack,s=START,c=0,len=0,f=null]],remote=WebSocketRemoteEndpoint@6e0690[batching=true],incoming=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],outgoing=ExtensionStack[queueSize=0,extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]]
2019-03-01 12:09:42.607 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"8c2aed0d-1417-46b5-823a-743c2ff6b583","params":{}}}
2019-03-01 12:10:12.618 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"ebd6fe6d-92fc-4443-ada1-d9934aa5826c","params":{}}}
2019-03-01 12:10:42.624 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"7b6b91bd-dc10-44df-9f33-744aecd4fd13","params":{}}}
2019-03-01 12:11:12.628 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"d43cc4f3-11ab-4c1f-bf1d-20a0aa4c999a","params":{}}}
2019-03-01 12:11:42.634 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"5d1d2b11-5a38-4416-830d-aa9639fe038e","params":{}}}
2019-03-01 12:12:12.638 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"3fa69e3c-8c57-43c2-8034-dae001ec1c19","params":{}}}
2019-03-01 12:12:42.644 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"227496ef-91e6-48f1-b00a-ce491af68217","params":{}}}
Celaeno1 picture Celaeno1 on 1 Mar 2019

We get a network error here

2019-03-01 12:07:57.376 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketError

The binding waits a minute and we try to reconnect here but fail to even connect to the HUB

2019-03-01 12:08:12.394 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketClose 1006 WebSocket Read EOF

We wait a minute again and are able to connect

2019-03-01 12:09:12.603 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketConnect WebSocketSession[websocket=JettyListenerEventDriver[

This would seem to me to be network related and the binding is handling it as it should.

digitaldan picture digitaldan on 1 Mar 2019
👍1

@digitaldan

Tonight from 20:08 til now (9:02) =13 hours. No errors. Seems to be there were network errors before. If there are no other issues reported from other users you could merge to master...

Celaeno1 picture Celaeno1 on 2 Mar 2019

Thanks @Celaeno1 , good to know the binding is working. Fixed was merged a few days ago, https://github.com/openhab/openhab2-addons/pull/5011.

digitaldan picture digitaldan on 2 Mar 2019
❤1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

mjcumming picture mjcumming  路  5Comments
trailblazer2006 picture trailblazer2006  路  6Comments
IOOOTAlan picture IOOOTAlan  路  3Comments
gk4 picture gk4  路  3Comments
J-N-K picture J-N-K  路  6Comments