Harmony Hub - new activity causes "unhandled error" and hub to go offline

Craigers · April 14, 2019, 9:45pm

Platform information:
- Hardware: ESXI 6.7.0
- OS: Debian GNU/Linux 9 (stretch) VM
- Java Runtime Environment: java version “1.8.0_201”
- openHAB version: 2.5.0~S1558-1
- Harmony Binding version: “2.5.0.201903220233 │ HarmonyHub Binding”
Issue of the topic: Created a new Harmony Activity, causes disconnect and unhandled error

Not certain if anyone else has encountered this…

Harmony Hub firmware is updated to 4.15.250 and XMPP is enabled.

Today I created a new activity using the Harmony App on my Chromebook, and when changing to this activity my Harmony Hub goes offline in openHAB and errors are present in frontail. Changing to Activities that I have been using for over a year does not generate an error.

The Activity I have created is exactly the same a previously existing one (only a different name), no additional devices or changes have been made. I have only noticed this as I am using a rule to watch for the Activity to change, and while watching frontail for debug info saw this happen.

Here is the error:

2019-04-14 17:20:17.312 [WARN ] [ny.HarmonyClient$MyWebSocketListener] - Unhandled Error (closing connection)

2019-04-14 17:20:32.316 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null

2019-04-14 17:20:32.317 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:55559959' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-04-14 17:20:32.318 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:44169789' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-04-14 17:20:32.319 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating listeners with status OFFLINE

Has anyone else encountered this? Not certain if this is related to the updated Harmony Hub firmware or the Harmony Binding…

harmony.rules

rule "Activity changed"
when
    Item HarmonyHubHarmonyHub_Activity received update
then
    logInfo("Harmony", "Harmony Activity is now " + HarmonyHubHarmonyHub_Activity.state)
end

Any thoughts or suggestions?

Thanks
Craig

digitaldan · April 14, 2019, 10:28pm

Can you turn up the debugging on the harmony library and try again? In the openHAB console , the command would be:

log:set DEBUG com.digitaldan.harmony

see https://www.openhab.org/docs/administration/console.html for how to access the console.

Craigers · April 14, 2019, 11:23pm

Thanks for responding Dan.
I’ve tried to set up a log file for this but made an error somewhere…
Here is a copy and paste from frontail:

2019-04-14 19:17:39.253 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"4635edf0-999c-4c0b-b02a-784f980023bf","params":{}}}

2019-04-14 19:17:47.680 [WARN ] [ny.HarmonyClient$MyWebSocketListener] - Unhandled Error (closing connection)

2019-04-14 19:17:47.681 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketError

2019-04-14 19:17:47.681 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose null {}

2019-04-14 19:17:47.683 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketClose 1006 Disconnected

2019-04-14 19:17:47.683 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose Disconnected {}

2019-04-14 19:18:02.683 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null

2019-04-14 19:18:02.684 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:55559959' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-04-14 19:18:02.685 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:44169789' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-04-14 19:18:02.685 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating listeners with status OFFLINE

2019-04-14 19:19:02.683 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Connecting: host 192.168.1.59

2019-04-14 19:19:02.797 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketConnect WebSocketSession[websocket=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],behavior=CLIENT,connection=WebSocketClientConnection@15146e0c::SocketChannelEndPoint@6c201de8{/192.168.1.59:8088<->/192.168.1.72:42560,OPEN,fill=-,flush=-,to=0/300000}{io=1/0,kio=1,kro=1}->WebSocketClientConnection@15146e0c[ios=IOState@29228e08[CONNECTED,!in,out],f=Flusher@ceb4102[queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@18c162b0[ExtensionStack,s=START,c=0,len=0,f=null]],remote=WebSocketRemoteEndpoint@74e2f31d[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-04-14 19:19:02.800 [DEBUG] [nternal.handler.HarmonyDeviceHandler] - Updating harmonyhub:device:HarmonyHub:55559959:buttonPress

2019-04-14 19:19:02.801 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE

2019-04-14 19:19:02.804 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:55559959' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

Craig

digitaldan · April 15, 2019, 12:25am

hmm, I think we need to set this to TRACE level, also I don’t see it switching to the new activity, can you make sure you thats in the next log you post ? The only send command i see there is the ping (unless the error is being thrown before this). So in the console, paste

log:set TRACE com.digitaldan.harmony

Also lets turn up the binding level as well:

log:set DEBUG org.openhab.binding.harmonyhub

When you are done you can set it back to WARN to avoid flooding your log files with

log:set WARN com.digitaldan.harmony

Thanks

Craigers · April 15, 2019, 1:41am

log:set TRACE com.digitaldan.harmony

log:set DEBUG org.openhab.binding.harmonyhub

Both are set. I’ve Broken this into two copy and pastes.

This first is with an original activity “Shield TV” that did not have any errors.

2019-04-14 21:25:05.696 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"type":"connect.stateDigest?notify","data":{"sleepTimerId":-1,"runningZoneList":[],"sequence":false,"activityId":"34253132","errorCode":"200","syncStatus":0,"activitySetupState":false,"stateVersion":137,"tzOffset":"-14400","mode":3,"hubSwVersion":"4.15.250","deviceSetupState":[],"tzoffset":"-14400","isSetupComplete":true,"updates":{"106":"4.14.112","100":"4.14.112"},"discoveryServer":"https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc","configVersion":538,"activityStatus":1,"wifiStatus":1,"tz":"EST5EDT,M3.2.0,M11.1.0","runningActivityList":"24448571","time":1555291464,"hubUpdate":false,"contentVersion":142,"accountId":"7437024"}}

2019-04-14 21:25:05.697 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:25:05.697 [TRACE] [com.digitaldan.harmony.HarmonyClient] - DigestMessage 34253132

2019-04-14 21:25:05.697 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - status listener[org.openhab.binding.harmonyhub.internal.handler.HarmonyHubHandler@329dba9d] notified: Activity[34253132]:SHIELD TV - ACTIVITY_IS_STARTING

2019-04-14 21:25:05.697 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Received ACTIVITY_IS_STARTING activity status for SHIELD TV

2019-04-14 21:25:05.697 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarting triggered SHIELD_TV

2019-04-14 21:25:08.764 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"type":"connect.stateDigest?notify","data":{"sleepTimerId":-1,"runningZoneList":[],"sequence":false,"activityId":"34253132","errorCode":"200","syncStatus":0,"activitySetupState":false,"stateVersion":138,"tzOffset":"-14400","mode":3,"hubSwVersion":"4.15.250","deviceSetupState":[],"tzoffset":"-14400","isSetupComplete":true,"updates":{"106":"4.14.112","100":"4.14.112"},"discoveryServer":"https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc","configVersion":538,"activityStatus":2,"wifiStatus":1,"tz":"EST5EDT,M3.2.0,M11.1.0","runningActivityList":"24448571","time":1555291464,"hubUpdate":false,"contentVersion":142,"accountId":"7437024"}}

2019-04-14 21:25:08.764 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:25:08.764 [TRACE] [com.digitaldan.harmony.HarmonyClient] - DigestMessage 34253132

2019-04-14 21:25:08.764 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - status listener[org.openhab.binding.harmonyhub.internal.handler.HarmonyHubHandler@329dba9d] notified: Activity[34253132]:SHIELD TV - ACTIVITY_IS_STARTED

2019-04-14 21:25:08.764 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Received ACTIVITY_IS_STARTED activity status for SHIELD TV

2019-04-14 21:25:08.765 [vent.ChannelTriggeredEvent] - harmonyhub:hub:HarmonyHub:activityStarted triggered SHIELD_TV

2019-04-14 21:25:08.807 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"type":"harmony.engine?startActivityFinished","data":{"activityId":"34253132","errorCode":"200","errorString":"OK"}}

2019-04-14 21:25:08.807 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:25:08.807 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - ActivityFinishedMessage 34253132

2019-04-14 21:25:08.807 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating current activity to SHIELD TV

2019-04-14 21:25:08.809 [INFO ] [lipse.smarthome.model.script.Harmony] - Harmony Activity is now SHIELD TV

2019-04-14 21:25:08.809 [vent.ItemStateChangedEvent] - HarmonyHubHarmonyHub_Activity changed from Watch TV to SHIELD TV

2019-04-14 21:25:09.355 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"type":"connect.stateDigest?notify","data":{"sleepTimerId":-1,"runningZoneList":[],"sequence":false,"activityId":"34253132","errorCode":"200","syncStatus":0,"activitySetupState":false,"stateVersion":139,"tzOffset":"-14400","mode":3,"hubSwVersion":"4.15.250","deviceSetupState":[],"tzoffset":"-14400","isSetupComplete":true,"updates":{"106":"4.14.112","100":"4.14.112"},"discoveryServer":"https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc","configVersion":538,"activityStatus":2,"wifiStatus":1,"tz":"EST5EDT,M3.2.0,M11.1.0","runningActivityList":"34253132","time":1555291507,"hubUpdate":false,"contentVersion":142,"accountId":"7437024"}}

2019-04-14 21:25:09.355 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:25:09.355 [TRACE] [com.digitaldan.harmony.HarmonyClient] - DigestMessage 34253132

2019-04-14 21:25:24.932 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"65d5875c-cf54-4d4b-830a-13344e27a698","params":{}}}

2019-04-14 21:25:24.933 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 65d5875c-cf54-4d4b-830a-13344e27a698

2019-04-14 21:25:24.960 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"65d5875c-cf54-4d4b-830a-13344e27a698","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"65d5875c-cf54-4d4b-830a-13344e27a698"}}

2019-04-14 21:25:24.961 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:25:24.961 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 65d5875c-cf54-4d4b-830a-13344e27a698

2019-04-14 21:25:24.961 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 65d5875c-cf54-4d4b-830a-13344e27a698

2019-04-14 21:25:27.631 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:25:54.933 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"39af6b5b-6f02-49a7-b36f-661a0357ead9","params":{}}}

2019-04-14 21:25:54.933 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 39af6b5b-6f02-49a7-b36f-661a0357ead9

2019-04-14 21:25:54.966 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"39af6b5b-6f02-49a7-b36f-661a0357ead9","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"39af6b5b-6f02-49a7-b36f-661a0357ead9"}}

2019-04-14 21:25:54.966 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:25:54.966 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 39af6b5b-6f02-49a7-b36f-661a0357ead9

2019-04-14 21:25:54.966 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 39af6b5b-6f02-49a7-b36f-661a0357ead9

This is when I started the new activity “Kodi”. It is set up exactly like “Shield TV” in the Harmony app. I note it also never says it has changed to “Kodi”, and reports as being “Shield TV” at 21:27:20.731. PaperUI says it is “Shield TV” as well. This is the same for any activity I change from it reports it is the activity i was just using (eg. Watch TV, Use Computer…). Side note my Elite remote functions properly per the activity selected.

2019-04-14 21:26:05.603 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"type":"connect.stateDigest?notify","data":{"sleepTimerId":-1,"runningZoneList":[],"sequence":false,"activityId":"39339472","errorCode":"200","syncStatus":0,"activitySetupState":false,"stateVersion":140,"tzOffset":"-14400","mode":3,"hubSwVersion":"4.15.250","deviceSetupState":[],"tzoffset":"-14400","isSetupComplete":true,"updates":{"106":"4.14.112","100":"4.14.112"},"discoveryServer":"https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc","configVersion":538,"activityStatus":1,"wifiStatus":1,"tz":"EST5EDT,M3.2.0,M11.1.0","runningActivityList":"34253132","time":1555291507,"hubUpdate":false,"contentVersion":142,"accountId":"7437024"}}

2019-04-14 21:26:05.603 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:26:05.603 [WARN ] [ny.HarmonyClient$MyWebSocketListener] - Unhandled Error (closing connection)

	at com.digitaldan.harmony.HarmonyClient$MyWebSocketListener.onWebSocketText(HarmonyClient.java:510) ~[?:?]

2019-04-14 21:26:05.604 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketError

	at com.digitaldan.harmony.HarmonyClient$MyWebSocketListener.onWebSocketText(HarmonyClient.java:510) [243:org.openhab.binding.harmonyhub:2.5.0.201903220233]

2019-04-14 21:26:05.608 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose null {}

2019-04-14 21:26:05.609 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketClose 1006 Disconnected

2019-04-14 21:26:05.609 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - notifyClose Disconnected {}

2019-04-14 21:26:20.609 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: null

2019-04-14 21:26:20.610 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:55559959' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-04-14 21:26:20.611 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:44169789' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

2019-04-14 21:26:20.611 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating listeners with status OFFLINE

2019-04-14 21:26:27.639 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:27:20.609 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Connecting: host 192.168.1.59

2019-04-14 21:27:20.617 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Sending {"cmd":"setup.account?getProvisionInfo","id":"c18791c8-3597-4789-950c-64ab228de5d2","params":{}}

2019-04-14 21:27:20.670 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Discovery response for hos 192.168.1.59 : {"id":"c18791c8-3597-4789-950c-64ab228de5d2","msg":"OK","data":{"email":"dummy@mail.com","username":"dummy@mail.com","activeRemoteId":7773856,"discoveryServer":"https:\/\/svcs.myharmony.com\/Discovery\/Discovery.svc","se":true,"susChannel":"production","mode":3,"language":"en-US","accountId":"7437024"},"code":"200"}

2019-04-14 21:27:20.726 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - onWebSocketConnect WebSocketSession[websocket=JettyListenerEventDriver[com.digitaldan.harmony.HarmonyClient$MyWebSocketListener],behavior=CLIENT,connection=WebSocketClientConnection@15149ef8::SocketChannelEndPoint@5fb385a5{/192.168.1.59:8088<->/192.168.1.72:42964,OPEN,fill=-,flush=-,to=0/300000}{io=1/0,kio=1,kro=1}->WebSocketClientConnection@15149ef8[ios=IOState@1ab11037[CONNECTED,!in,out],f=Flusher@108678f2[queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@2b614c94[ExtensionStack,s=START,c=0,len=0,f=null]],remote=WebSocketRemoteEndpoint@68bc7af0[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-04-14 21:27:20.727 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from OFFLINE (COMMUNICATION_ERROR): Could not connect: null to ONLINE

2019-04-14 21:27:20.727 [DEBUG] [nternal.handler.HarmonyDeviceHandler] - Updating harmonyhub:device:HarmonyHub:55559959:buttonPress

2019-04-14 21:27:20.728 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:55559959' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2019-04-14 21:27:20.728 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:55559959' has been updated.

2019-04-14 21:27:20.729 [DEBUG] [nternal.handler.HarmonyDeviceHandler] - Updating harmonyhub:device:HarmonyHub:44169789:buttonPress

2019-04-14 21:27:20.730 [hingStatusInfoChangedEvent] - 'harmonyhub:device:HarmonyHub:44169789' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2019-04-14 21:27:20.730 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:device:HarmonyHub:44169789' has been updated.

2019-04-14 21:27:20.730 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating listeners with status ONLINE

2019-04-14 21:27:20.730 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating current activity to SHIELD TV

2019-04-14 21:27:20.731 [DEBUG] [b.internal.handler.HarmonyHubHandler] - Updating harmonyhub:hub:HarmonyHub:currentActivity

2019-04-14 21:27:20.731 [INFO ] [lipse.smarthome.model.script.Harmony] - Harmony Activity is now SHIELD TV

2019-04-14 21:27:20.734 [me.event.ThingUpdatedEvent] - Thing 'harmonyhub:hub:HarmonyHub' has been updated.

2019-04-14 21:27:27.646 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:27:50.726 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"a70ef8f9-3864-43c8-9641-717ef40c085f","params":{}}}

2019-04-14 21:27:50.727 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id a70ef8f9-3864-43c8-9641-717ef40c085f

2019-04-14 21:27:50.749 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"a70ef8f9-3864-43c8-9641-717ef40c085f","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"a70ef8f9-3864-43c8-9641-717ef40c085f"}}

2019-04-14 21:27:50.750 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:27:50.750 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID a70ef8f9-3864-43c8-9641-717ef40c085f

2019-04-14 21:27:50.750 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID a70ef8f9-3864-43c8-9641-717ef40c085f

2019-04-14 21:28:20.728 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"69077234-3791-4693-b1d4-ef4590b8f5d0","params":{}}}

2019-04-14 21:28:20.728 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 69077234-3791-4693-b1d4-ef4590b8f5d0

2019-04-14 21:28:20.761 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"69077234-3791-4693-b1d4-ef4590b8f5d0","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"69077234-3791-4693-b1d4-ef4590b8f5d0"}}

2019-04-14 21:28:20.762 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:28:20.776 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 69077234-3791-4693-b1d4-ef4590b8f5d0

2019-04-14 21:28:20.777 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 69077234-3791-4693-b1d4-ef4590b8f5d0

2019-04-14 21:28:27.654 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:28:50.728 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"a256bc19-0e31-486e-972f-1ff0d43aeb92","params":{}}}

2019-04-14 21:28:50.729 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id a256bc19-0e31-486e-972f-1ff0d43aeb92

2019-04-14 21:28:50.751 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"a256bc19-0e31-486e-972f-1ff0d43aeb92","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"a256bc19-0e31-486e-972f-1ff0d43aeb92"}}

2019-04-14 21:28:50.751 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:28:50.751 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID a256bc19-0e31-486e-972f-1ff0d43aeb92

2019-04-14 21:28:50.751 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID a256bc19-0e31-486e-972f-1ff0d43aeb92

2019-04-14 21:29:20.730 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"f4bf8b3a-14c6-457c-a80c-cbe791273562","params":{}}}

2019-04-14 21:29:20.730 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id f4bf8b3a-14c6-457c-a80c-cbe791273562

2019-04-14 21:29:20.750 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"f4bf8b3a-14c6-457c-a80c-cbe791273562","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"f4bf8b3a-14c6-457c-a80c-cbe791273562"}}

2019-04-14 21:29:20.750 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:29:20.751 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID f4bf8b3a-14c6-457c-a80c-cbe791273562

2019-04-14 21:29:20.751 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID f4bf8b3a-14c6-457c-a80c-cbe791273562

2019-04-14 21:29:27.662 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:29:50.730 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"d36f28f0-0c47-4a0d-814e-1e6401d8aa6a","params":{}}}

2019-04-14 21:29:50.731 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id d36f28f0-0c47-4a0d-814e-1e6401d8aa6a

2019-04-14 21:29:50.761 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"d36f28f0-0c47-4a0d-814e-1e6401d8aa6a","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"d36f28f0-0c47-4a0d-814e-1e6401d8aa6a"}}

2019-04-14 21:29:50.761 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:29:50.761 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID d36f28f0-0c47-4a0d-814e-1e6401d8aa6a

2019-04-14 21:29:50.761 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID d36f28f0-0c47-4a0d-814e-1e6401d8aa6a

2019-04-14 21:30:20.731 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"1d17f9a3-cd3a-474f-9590-99d98cb1b40c","params":{}}}

2019-04-14 21:30:20.731 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 1d17f9a3-cd3a-474f-9590-99d98cb1b40c

2019-04-14 21:30:20.768 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"1d17f9a3-cd3a-474f-9590-99d98cb1b40c","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"1d17f9a3-cd3a-474f-9590-99d98cb1b40c"}}

2019-04-14 21:30:20.769 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:30:20.769 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 1d17f9a3-cd3a-474f-9590-99d98cb1b40c

2019-04-14 21:30:20.769 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 1d17f9a3-cd3a-474f-9590-99d98cb1b40c

2019-04-14 21:30:27.673 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:30:50.732 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"2ec8734d-e42c-4d67-a28d-e486668fe1e7","params":{}}}

2019-04-14 21:30:50.732 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 2ec8734d-e42c-4d67-a28d-e486668fe1e7

2019-04-14 21:30:50.762 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"2ec8734d-e42c-4d67-a28d-e486668fe1e7","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"2ec8734d-e42c-4d67-a28d-e486668fe1e7"}}

2019-04-14 21:30:50.762 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:30:50.762 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 2ec8734d-e42c-4d67-a28d-e486668fe1e7

2019-04-14 21:30:50.762 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 2ec8734d-e42c-4d67-a28d-e486668fe1e7

2019-04-14 21:31:20.732 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"827e1518-ed44-43a5-8668-eb100641afc9","params":{}}}

2019-04-14 21:31:20.732 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 827e1518-ed44-43a5-8668-eb100641afc9

2019-04-14 21:31:20.763 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"827e1518-ed44-43a5-8668-eb100641afc9","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"827e1518-ed44-43a5-8668-eb100641afc9"}}

2019-04-14 21:31:20.763 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:31:20.763 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 827e1518-ed44-43a5-8668-eb100641afc9

2019-04-14 21:31:20.763 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 827e1518-ed44-43a5-8668-eb100641afc9

2019-04-14 21:31:27.677 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:31:50.733 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"996c05be-d5be-48c4-84ac-948f9ae5b0b5","params":{}}}

2019-04-14 21:31:50.733 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 996c05be-d5be-48c4-84ac-948f9ae5b0b5

2019-04-14 21:31:50.754 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"996c05be-d5be-48c4-84ac-948f9ae5b0b5","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"996c05be-d5be-48c4-84ac-948f9ae5b0b5"}}

2019-04-14 21:31:50.754 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:31:50.754 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 996c05be-d5be-48c4-84ac-948f9ae5b0b5

2019-04-14 21:31:50.754 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 996c05be-d5be-48c4-84ac-948f9ae5b0b5

2019-04-14 21:32:20.734 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"0cc4ece1-83f0-4d33-891f-791fe3da746b","params":{}}}

2019-04-14 21:32:20.734 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 0cc4ece1-83f0-4d33-891f-791fe3da746b

2019-04-14 21:32:20.760 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"0cc4ece1-83f0-4d33-891f-791fe3da746b","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"0cc4ece1-83f0-4d33-891f-791fe3da746b"}}

2019-04-14 21:32:20.760 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:32:20.760 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 0cc4ece1-83f0-4d33-891f-791fe3da746b

2019-04-14 21:32:20.760 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 0cc4ece1-83f0-4d33-891f-791fe3da746b

2019-04-14 21:32:27.685 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

2019-04-14 21:32:43.498 [DEBUG] [discovery.HarmonyHubDiscoveryService] - StartScan called

2019-04-14 21:32:43.499 [DEBUG] [discovery.HarmonyHubDiscoveryService] - Creating Harmony server on port 45941

2019-04-14 21:32:50.734 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"4cbe5992-eef0-4b3f-b79f-bad58de1e4db","params":{}}}

2019-04-14 21:32:50.734 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 4cbe5992-eef0-4b3f-b79f-bad58de1e4db

2019-04-14 21:32:50.958 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"4cbe5992-eef0-4b3f-b79f-bad58de1e4db","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"4cbe5992-eef0-4b3f-b79f-bad58de1e4db"}}

2019-04-14 21:32:50.958 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:32:50.958 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 4cbe5992-eef0-4b3f-b79f-bad58de1e4db

2019-04-14 21:32:50.958 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 4cbe5992-eef0-4b3f-b79f-bad58de1e4db

2019-04-14 21:33:20.735 [DEBUG] [com.digitaldan.harmony.HarmonyClient] - Sending: {"hbus":{"cmd":"vnd.logitech.connect/vnd.logitech.ping","id":"29e493be-78c3-487b-95e4-80843ccd1fa9","params":{}}}

2019-04-14 21:33:20.735 [TRACE] [com.digitaldan.harmony.HarmonyClient] - writeSuccess for id 29e493be-78c3-487b-95e4-80843ccd1fa9

2019-04-14 21:33:20.757 [TRACE] [com.digitaldan.harmony.HarmonyClient] - onWebSocketText {"cmd":"vnd.logitech.connect\/vnd.logitech.ping","code":200,"id":"29e493be-78c3-487b-95e4-80843ccd1fa9","msg":"OK","data":{"status":"alive","uuid":"d74310697280ebfee21efec77dab438965d27ff3","susTrigger":"websocket","id":"29e493be-78c3-487b-95e4-80843ccd1fa9"}}

2019-04-14 21:33:20.758 [TRACE] [harmony.messages.MessageDeserializer] - Calling fromJsonElement

2019-04-14 21:33:20.758 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Looking for future for ID 29e493be-78c3-487b-95e4-80843ccd1fa9

2019-04-14 21:33:20.758 [TRACE] [com.digitaldan.harmony.HarmonyClient] - Calling for future for ID 29e493be-78c3-487b-95e4-80843ccd1fa9

2019-04-14 21:33:27.694 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0defa359a:Main_Zone' has been updated.

Craig

digitaldan · April 16, 2019, 2:28pm

Hi Craig, fyi i have not forgotten about this, but i’m away on business for the week (and next). As soon as i can i i will take a look.

digitaldan · April 16, 2019, 2:34pm

In the mean time, i believe in TRACE mode, when the binding starts up the harmony lib will output a huge JSON string to the log file which represents the entire harmony config ( all activities, devices, button presses). Can PM that to me ?

Craigers · April 16, 2019, 10:23pm

No worries Dan I appreciate your help.

PMing to you now.

Craig

Maarten_Stil · May 7, 2022, 8:10am

In search of troubleshooting my issue with a new activity on my Harmony Hub, I came across this post.
I think I have the exact same issue as the OP. I had 3 activities active on my Hub and created another one. When I trigger that last activity, the hub goes offline in OH and after 1 minute it comes back.

EDIT: I did a reset of my hub and resynced everything. Now it works again.

kdub454 · February 29, 2024, 11:36pm

Hi there,

I’m still seeing this behavior, it happens every few weeks.
Any chance we can re-open this and take a look?

Thanks,

Kent