Upgraded from Harmony Ultimate to Harmony Elite - Can not connect - failed with -911/Device not ready

So I recently upgraded from a Harmony Ultimate to a Harmony Elite and in doing so, swapped out the associated hub. The hub is running firmware 4.15.250 and I have enabled XMPP on it. My internal network uses MAC address to IP mappings via DHCP so I updated the config to vend the same IP address to the new hub. I have confirmed that the hub is using the same IP address, reloaded LUUP, rebooted the hub but to no avail. I’m running the latest 3.16 plugin from the MIOS app store. Here is what I see in the logs:

$ veraLogs.sh | grep -i harmony
09	01/22/20 10:56:47.452	JobHandler_LuaUPnP::Run device 135 ptr 0xdcd890 Harmony Control room 2 type urn:schemas-rboer-com:device:Harmony135:1 cat 3:-1 id HAM135_CNTRL parent 0/0xe940b0 upnp: 0 plugin:8066 pnp:0 mac: ip: <0x77fcf320>
09	01/22/20 10:56:47.452	JobHandler_LuaUPnP::Run device 137 ptr 0xdce400 HRM: Pioneer AV Receiver room 0 type urn:schemas-rboer-com:device:HarmonyDevice135_55865429:1 cat 3:-1 id HAM135_55865429 parent 135/0xe973d8 upnp: 0 plugin:0 pnp:0 mac: ip: <0x77fcf320>
09	01/22/20 10:56:47.452	JobHandler_LuaUPnP::Run device 136 ptr 0xdcdf08 HRM: TiVo DVR room 0 type urn:schemas-rboer-com:device:HarmonyDevice135_55865460:1 cat 3:-1 id HAM135_55865460 parent 135/0xe958c0 upnp: 0 plugin:0 pnp:0 mac: ip: <0x77fcf320>
06	01/22/20 10:57:00.451	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: LinkStatus was: Hub connection failed. Check IP Address. now: Starting... #hooks: 0 upnp: 0 skip: 0 v:0x10ad628/NONE duplicate:0 <0x775f8520>
06	01/22/20 10:57:00.452	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: IconSet was: 0 now: 3 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x775f8520>
50	01/22/20 10:57:00.452	luup_log:135: Harmony Control: Harmony device #135 is initializing! <0x775f8520>
50	01/22/20 10:57:00.453	luup_log:135: Harmony Control: We are running on Vera UI7. <0x775f8520>
08	01/22/20 10:57:00.454	luup_log:135: Harmony Control_info: UIVersion is current : 3.5. <0x775f8520>
08	01/22/20 10:57:00.454	luup_log:135: Harmony Control_info: Changing Harmony Hub: IP address 192.168.0.131. <0x775f8520>
01	01/22/20 10:57:00.483	luup_log:135: Harmony Control_error: Connect, failed to open web-socket to hub 192.168.0.131, err Websocket Handshake failed. <0x775f8520>
06	01/22/20 10:57:00.484	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: IconSet was: 3 now: 4 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x775f8520>
01	01/22/20 10:57:00.484	luup_log:135: Harmony Control_error: Initialize, unable to reconnect on IP address 192.168.0.131. <0x775f8520>
06	01/22/20 10:57:00.485	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: LinkStatus was: Starting... now: Hub connection failed. Check IP Address. #hooks: 0 upnp: 0 skip: 0 v:0x10ad628/NONE duplicate:0 <0x775f8520>
01	01/22/20 10:57:00.487	LuaInterface::CallFunction_Startup-2 device 135 function Harmony_init failed Harmony Control with return false <0x775f8520>
01	01/22/20 10:57:00.499	LuImplementation::StartLua running startup code for 135 I_Harmony.xml failed <0x775f8520>

Any ideas as to what I can do to troubleshoot further?

Hi Blacey,

For some reason the websocket gets opened, but after that the response is not as expected. It is a pretty low level error that I did not include standard debugging messages for. What you can try is at line 906 add:

log.Error(line)

and try again so i can see what comes back from the hub and how that is different than expected.

Cheers Rene

Thanks @reneboer. I made the following change:

(base) [blacey@bbl ~/Projects/Vera/vera-Harmony-Hub/chm-ludl (master *)]$ git diff
diff --git a/chm-ludl/L_Harmony.lua b/chm-ludl/L_Harmony.lua
index 9787e8d..e7f7f97 100644
--- a/chm-ludl/L_Harmony.lua
+++ b/chm-ludl/L_Harmony.lua
@@ -904,6 +904,7 @@ local function wsAPI()
                                return nil,err,nil
                        end
                        -- if we receive HTTP/1.1 101 Switching Protocols then assume connect is ok.
+                       log.Error(line)
                        if line == "HTTP/1.1 101 Switching Protocols" then hdr_ok = true end
                until line == ''
                if not hdr_ok then

And this is what I see in the logs…

|01|01/23/20 15:34:35.480|luup_log:135: Harmony Control_error: HTTP/1.1 401 Wrong hubId <0x77090520>|
|---|---|---|
|01|01/23/20 15:34:35.480|luup_log:135: Harmony Control_error:  <0x77090520>|
|01|01/23/20 15:34:35.480|luup_log:135: Harmony Control_error: Connect, failed to open web-socket to hub 192.168.0.131, err Websocket Handshake failed. <0x77090520>|
|06|01/23/20 15:34:35.481|Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: IconSet was: 3 now: 4 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x77090520>|
|01|01/23/20 15:34:35.483|luup_log:135: Harmony Control_error: Initialize, unable to reconnect on IP address 192.168.0.131. <0x77090520>|
|06|01/23/20 15:34:35.484|Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: LinkStatus was: Starting... now: Hub connection failed. Check IP Address. #hooks: 0 upnp: 0 skip: 0 v:0x1476910/NONE duplicate:0 <0x77090520>|
|06|01/23/20 15:34:35.484|Device_Variable::m_szValue_set device: 135 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 1 now: 2 #hooks: 0 upnp: 0 skip: 0 v:0x12d8440/NONE duplicate:0 <0x77090520>|
|06|01/23/20 15:34:35.485|Device_Variable::m_szValue_set device: 135 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailureTime was: 1579811564 now: 1579811675 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x77090520>|
|01|01/23/20 15:34:35.486|LuaInterface::CallFunction_Startup-2 device 135 function Harmony_init failed Harmony Control with return false <0x77090520>|
|06|01/23/20 15:34:35.487|Device_Variable::m_szValue_set device: 135 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 2 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0x12d8440/NONE duplicate:0 <0x77090520>|
|06|01/23/20 15:34:35.488|Device_Variable::m_szValue_set device: 135 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailureTime was: 1579811675 now: 1579811675 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x77090520>|
|01|01/23/20 15:34:35.489|LuImplementation::StartLua running startup code for 135 I_Harmony.xml failed <0x77090520>|

Hi Blacey,

Can you try to empty the RemoteID variable. It seems an optimization I put in keeps the ID of the old hub. I put out V3.17 to handle this scenario.

Cheers Rene

@reneboer :+1:

I reset the variable as follows:

Check that service id and variable are correct before setting (get value):

$ curl -L "http://vera.home:3480/data_request?id=variableget&DeviceNum=135&serviceId=urn:rboer-com:serviceId:Harmony1&Variable=RemoteID"
3581833

Set the RemoteID variable to empty (turns out this actually deletes the variable)

$ curl -L "http://vera.home:3480/data_request?id=variableset&DeviceNum=135&serviceId=urn:rboer-com:serviceId:Harmony1&Variable=RemoteID&Value="
OK

Confirm change:

curl -L "http://vera.home:3480/data_request?id=variableget&DeviceNum=135&serviceId=urn:rboer-com:serviceId:Harmony1&Variable=RemoteID"
Error: variable not found

Reload LUUP and check logs:

50	01/24/20 8:06:39.287	luup_log:135: Harmony Control: Harmony device #135 is initializing! <0x769b6520>
50	01/24/20 8:06:39.287	luup_log:135: Harmony Control: We are running on Vera UI7. <0x769b6520>
06	01/24/20 8:06:39.288	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: RemoteID was: EMPTY now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x769b6520>
08	01/24/20 8:06:39.290	luup_log:135: Harmony Control_info: UIVersion is current : 3.5. <0x769b6520>
08	01/24/20 8:06:39.290	luup_log:135: Harmony Control_info: Changing Harmony Hub: IP address 192.168.0.131. <0x769b6520>
50	01/24/20 8:06:39.290	luup_log:135: Harmony Control_debug: Retrieving Harmony Hub information. <0x769b6520>
50	01/24/20 8:06:39.339	luup_log:135: Harmony Control_debug: Hub details : 15879459, 13657763, bruce@blacey.com. <0x769b6520>
06	01/24/20 8:06:39.339	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: RemoteID was:  now: 15879459 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x769b6520>
06	01/24/20 8:06:39.340	Device_Variable::m_szValue_set device: 135 service: urn:rboer-com:serviceId:Harmony1 variable: AccountID was: 3866047 now: 13657763 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x769b6520>
01	01/24/20 8:06:39.379	luup_log:135: Harmony Control_error: line: HTTP/1.1 101 Switching Protocols <0x769b6520>
01	01/24/20 8:06:39.379	luup_log:135: Harmony Control_error: line: Upgrade: websocket <0x769b6520>
01	01/24/20 8:06:39.379	luup_log:135: Harmony Control_error: line: Connection: upgrade <0x769b6520>
01	01/24/20 8:06:39.380	luup_log:135: Harmony Control_error: line: Sec-Websocket-Accept: erB0A1XLw/Bib49AAjuURoiMPZ4= <0x769b6520>
01	01/24/20 8:06:39.380	luup_log:135: Harmony Control_error: line:  <0x769b6520>
50	01/24/20 8:06:39.380	luup_log:135: Harmony Control_debug: Web-socket to Hub is opened... <0x769b6520>
50	01/24/20 8:06:39.382	luup_log:135: Harmony Control_debug: Button definitions found : 4 <0x769b6520>
50	01/24/20 8:06:39.382	luup_log:135: Harmony Control_debug: Harmony Hub Control: init_module completed. <0x769b6520>
08	01/24/20 8:06:42.101	luup_log:135: Harmony Control_info: Harmony device #135 is finishing start up! <0x7456d520>

The Plugin started up and proceeded to add child devices, etc. Thanks a ton for your help. I will restore my system to the 3.16 version sans logging.

One final question, am I correct in my understanding that I need XMPP enabled or does your plugin work around the XMPP dependency (I guess I could just try it).

Hi Blacey,

Good to hear it is working again. V3.17 should be better at handling it, but I need a bit more time to make a true clean solution.

The plugin uses WebSockets so no need to enable the XMPP on the Hub.

Cheers Rene

Hi Rene,

Thanks for your help resolving my hub-upgrade issue and the XMPP clarification. Swapping out hubs is probably and edge case but good to know you are working on a solution. Thanks again for your help and a great plugin!

Cheers,
Bruce

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.