Controller did not respond

I’m trying ALTUI on top of openLuup on a raspberry pi with a UZB stick and Zway (no Vera). I’m testing with one door sensor and it seems to work. However, ALTUI repeatedly says “Controller did not respond” in its message area. In the openLuup log file at the same time I see this. I’m not sure how to debug it. What do these lines mean? Note that I used the developer branch of openLuup from about 2 weeks ago to pick up the Zway plug in.

2016-10-20 09:26:01.437 openLuup.server:: new client connection: tcp{client}: 0x3adf70
2016-10-20 09:26:01.519 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=555764392&Timeout=60&MinimumDelay=1500&_=1476979698666 HTTP/1.0 tcp{client}: 0x3adf70
2016-10-20 09:26:34.106 openLuup.server:: closing client connection: tcp{client}: 0x3c7448
2016-10-20 09:27:01.470 openLuup.server:: receive error: closed tcp{client}: 0x3adf70
2016-10-20 09:27:01.974 openLuup.server:: error ‘closed’ sending 164 bytes to tcp{client}: 0x3adf70
2016-10-20 09:27:01.974 openLuup.server:: …only 0 bytes sent
2016-10-20 09:27:01.974 openLuup.server:: error ‘closed’ sending 5 bytes to tcp{client}: 0x3adf70
2016-10-20 09:27:01.974 openLuup.server:: …only 0 bytes sent
2016-10-20 09:27:01.974 openLuup.server:: error ‘closed’ sending 990 bytes to tcp{client}: 0x3adf70
2016-10-20 09:27:01.974 openLuup.server:: …only 0 bytes sent
2016-10-20 09:27:01.974 openLuup.server:: error ‘closed’ sending 2 bytes to tcp{client}: 0x3adf70
2016-10-20 09:27:01.974 openLuup.server:: …only 0 bytes sent
2016-10-20 09:27:01.975 openLuup.server:: error ‘closed’ sending 5 bytes to tcp{client}: 0x3adf70
2016-10-20 09:27:01.975 openLuup.server:: …only 0 bytes sent
2016-10-20 09:27:01.975 openLuup.server:: request completed (990 bytes, 1 chunks, 60455 ms) tcp{client}: 0x3adf70
2016-10-20 09:27:03.324 openLuup.server:: new client connection: tcp{client}: 0x2bed38

I’d rather like to the a log starting from a luup reload to see what might be happening earlier. This log just shows one connection being dropped.

If you try this from a web browser, does it respond with all the user_data?

http://openLuupIP:3480/data_request?id=user_data

Yes, the user_data does seem to be returned. Here’s a larger sample of a log file just after a reload:

2016-10-20 12:00:19.561 :: openLuup STARTUP ::
2016-10-20 12:00:19.561 openLuup.init:: version 2016.08.29 @akbooer
2016-10-20 12:00:19.605 openLuup.scheduler:: version 2016.08.23 @akbooer
2016-10-20 12:00:19.606 openLuup.wsapi:: version 2016.07.17 @akbooer
2016-10-20 12:00:19.607 openLuup.server:: version 2016.09.17 @akbooer
2016-10-20 12:00:19.613 openLuup.rooms:: version 2016.06.23 @akbooer
2016-10-20 12:00:19.617 openLuup.scenes:: version 2016.05.19 @akbooer
2016-10-20 12:00:19.621 openLuup.chdev:: version 2016.07.12 @akbooer
2016-10-20 12:00:19.622 openLuup.userdata:: version 2016.09.17 @akbooer
2016-10-20 12:00:19.622 openLuup.requests:: version 2016.08.22 @akbooer
2016-10-20 12:00:19.624 openLuup.io:: version 2016.04.30 @akbooer
2016-10-20 12:00:19.624 openLuup.luup:: version 2016.07.20 @akbooer
2016-10-20 12:00:19.625 luup.create_device:: [1] D_ZWaveNetwork.xml / /
2016-10-20 12:00:19.636 luup.create_device:: [2] D_openLuup.xml / I_openLuup.xml / D_openLuup.json
2016-10-20 12:00:19.637 openLuup.init:: loading configuration user_data.json
2016-10-20 12:00:19.637 openLuup.userdata:: loading user_data json…
2016-10-20 12:00:19.664 openLuup.userdata:: loading rooms…
2016-10-20 12:00:19.664 openLuup.userdata:: room#1 ‘Garage’
2016-10-20 12:00:19.664 openLuup.userdata:: …room loading completed
2016-10-20 12:00:19.664 openLuup.userdata:: loading devices…
2016-10-20 12:00:19.664 luup.create_device:: [1] D_ZWaveNetwork.xml / /
2016-10-20 12:00:19.719 luup.create_device:: [3] D_ALTUI.xml / I_ALTUI.xml / D_ALTUI_UI7.json
2016-10-20 12:00:19.727 luup.create_device:: [4] D_AltAppStore.xml / I_AltAppStore.xml / D_AltAppStore.json
2016-10-20 12:00:19.736 luup.create_device:: [5] D_ZWay.xml / I_ZWay.xml / D_ZWay.json
2016-10-20 12:00:19.737 luup.create_device:: [6] D_MotionSensor1.xml / /
2016-10-20 12:00:19.737 openLuup.userdata:: loading scenes…
2016-10-20 12:00:19.737 openLuup.userdata:: [1] Garage Sensor Battery Low
2016-10-20 12:00:19.738 openLuup.userdata:: [2] Garage Opening
2016-10-20 12:00:19.738 openLuup.userdata:: number of scenes = 2
2016-10-20 12:00:19.738 openLuup.userdata:: scene#1 ‘Garage Sensor Battery Low’
2016-10-20 12:00:19.738 openLuup.userdata:: scene#2 ‘Garage Opening’
2016-10-20 12:00:19.738 openLuup.userdata:: …scene loading completed
2016-10-20 12:00:19.738 openLuup.userdata:: loading installed plugin info…
2016-10-20 12:00:19.738 openLuup.userdata:: [openLuup] openLuup (16.10.4)
2016-10-20 12:00:19.738 openLuup.userdata:: [8246] Alternate UI (1.99.beta)
2016-10-20 12:00:19.738 openLuup.userdata:: [AltAppStore] Alternate App Store (16.8.31)
2016-10-20 12:00:19.738 openLuup.userdata:: [VeraBridge] VeraBridge (not.installed)
2016-10-20 12:00:19.738 openLuup.userdata:: [Z-Way] Z-Way (16.8.30)
2016-10-20 12:00:19.738 openLuup.userdata:: [Arduino] MySensors (not.installed)
2016-10-20 12:00:19.739 openLuup.userdata:: [8211] DataYours (not.installed)
2016-10-20 12:00:19.739 openLuup.userdata:: …user_data loading completed
2016-10-20 12:00:19.739 openLuup.init:: running openLuup_STARTUP
2016-10-20 12:00:19.739 luup_log:0: startup code completed
2016-10-20 12:00:19.739 openLuup.init:: init phase completed
2016-10-20 12:00:19.739 openLuup.server:: starting HTTP server on 192.168.1.204:3480 tcp{server}: 0x615550
2016-10-20 12:00:19.739 openLuup.scheduler:: starting
2016-10-20 12:00:19.740 openLuup.scheduler:: [2] device startup
2016-10-20 12:00:19.740 luup_log:2: synch in 100.3 s
2016-10-20 12:00:19.740 luup.variable_set:2: 2.urn:upnp-org:serviceId:altui1.DisplayLine2 was: EMPTY now: #hooks:0
2016-10-20 12:00:19.740 luup.variable_set:2: 2.openLuup.Version was: EMPTY now: v16.10.4 #hooks:0
2016-10-20 12:00:19.740 luup.register_handler:2: global_function_name=HTTP_openLuup, request=openLuup
2016-10-20 12:00:19.740 luup.register_handler:2: global_function_name=HTTP_openLuup, request=openluup
2016-10-20 12:00:19.740 luup.chdev.append:: [AltAppStore] Alternate App Store
2016-10-20 12:00:19.740 luup.chdev.sync:: [2] openLuup, syncing children
2016-10-20 12:00:19.740 luup.variable_set:2: 2.openLuup.Memory_Mb was: EMPTY now: 1.8 #hooks:0
2016-10-20 12:00:19.740 luup.variable_set:2: 2.openLuup.CpuLoad was: EMPTY now: 0.2 #hooks:0
2016-10-20 12:00:19.741 luup.variable_set:2: 2.openLuup.Uptime_Days was: EMPTY now: 0 #hooks:0
2016-10-20 12:00:19.741 luup.variable_set:2: 2.urn:upnp-org:serviceId:altui1.DisplayLine1 was: EMPTY now: 2 Mb, cpu 0.2%, 0 days #hooks:0
2016-10-20 12:00:19.741 luup_log:2: 2 Mb, cpu 0.2%, 0 days
2016-10-20 12:00:19.741 openLuup.scheduler:: [2] device startup completed: status=true, msg=synch in 100.3 s, name=L_openLuup
2016-10-20 12:00:19.741 openLuup.scheduler:: [3] device startup
2016-10-20 12:00:19.741 luup_log:3: ALTUI: initstatus(3) starting version: v1.67
2016-10-20 12:00:19.741 openLuup.scheduler:: [3] device startup completed: status=nil, msg=nil, name=nil
2016-10-20 12:00:19.741 openLuup.scheduler:: [4] device startup
2016-10-20 12:00:19.741 luup_log:4: AltAppStore : starting…
2016-10-20 12:00:19.741 luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine1 was: AltAppStore now: AltAppStore #hooks:0
2016-10-20 12:00:19.742 luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine2 was: now: #hooks:0
2016-10-20 12:00:19.742 luup.set_failure:4: status = 0
2016-10-20 12:00:19.742 luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.CommFailure was: 0 now: 0 #hooks:0
2016-10-20 12:00:19.742 luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.CommFailureTime was: 0 now: 0 #hooks:0
2016-10-20 12:00:19.742 openLuup.scheduler:: [4] device startup completed: status=true, msg=OK, name=AltAppStore
2016-10-20 12:00:19.742 openLuup.scheduler:: [5] device startup
2016-10-20 12:00:19.742 luup_log:5: ZWay: v16.8.30
2016-10-20 12:00:19.770 luup.variable_set:5: 5.urn:upnp-org:serviceId:altui1.DisplayLine1 was: 5 vDevs, 1 nodes now: #hooks:0
2016-10-20 12:00:19.770 luup.set_failure:5: status = 0
2016-10-20 12:00:19.770 luup.variable_set:5: 5.urn:micasaverde-com:serviceId:HaDevice1.CommFailure was: 0 now: 0 #hooks:0
2016-10-20 12:00:19.770 luup.variable_set:5: 5.urn:micasaverde-com:serviceId:HaDevice1.CommFailureTime was: 0 now: 0 #hooks:0
2016-10-20 12:00:19.770 luup.register_handler:5: global_function_name=HTTP_Z-Way_5, request=z5
2016-10-20 12:00:19.804 luup.chdev.append:: [3-0-48-1] 3: Garage Motion
2016-10-20 12:00:19.804 luup.chdev.sync:: [5] Z-Way, syncing children
2016-10-20 12:00:19.805 luup.variable_set:5: 5.urn:upnp-org:serviceId:altui1.DisplayLine1 was: now: 5 vDevs, 1 nodes #hooks:0
2016-10-20 12:00:19.805 luup.chdev.sync:: [6] 3: Garage Motion, syncing children
2016-10-20 12:00:19.805 openLuup.scheduler:: [5] device startup completed: status=true, msg=OK, name=L_ZWay
2016-10-20 12:00:20.712 openLuup.server:: new client connection: tcp{client}: 0x634458
2016-10-20 12:00:20.797 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=555764709&Timeout=60&MinimumDelay=1500&=1476989916817 HTTP/1.0 tcp{client}: 0x634458
2016-10-20 12:00:20.798 luup_log:3: ALTUI: startupDeferred, called on behalf of device:3
2016-10-20 12:00:20.798 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.LocalHome was: now: #hooks:0
2016-10-20 12:00:20.804 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Version was: v1.67 now: v1.67 #hooks:0
2016-10-20 12:00:20.809 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.DataStorageProviders was: {“emoncms”:{“url”:“”,“callback”:“sendValueToStorage_emoncms”,“parameters”:[{“default”:1,“type”:“number”,“key”:“node… now: {“emoncms”:{“url”:”“,“callback”:“sendValueToStorage_emoncms”,“parameters”:[{“key”:“nodeid”,“type”:“number”,“default… #hooks:0
2016-10-20 12:00:20.812 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.DataStorageProviders was: {“emoncms”:{“url”:””,“callback”:“sendValueToStorage_emoncms”,“parameters”:[{“key”:“nodeid”,“type”:“number”,“default… now: {“emoncms”:{“url”:”",“callback”:“sendValueToStorage_emoncms”,“parameters”:[{“default”:1,“type”:“number”,“key”:"node… #hooks:0
2016-10-20 12:00:20.813 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToSend was: now: #hooks:0
2016-10-20 12:00:20.813 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.RemoteVariablesToWatch was: now: #hooks:0
2016-10-20 12:00:20.814 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-6#2#new == 1 and old == 0#;urn:micasaverde-com:serviceId:Ha… now: urn:micasaverde-com:serviceId:SecuritySensor1#Tripped#0-6#2#new == 1 and old == 0#;urn:micasaverde-com:serviceId:Ha… #hooks:0
2016-10-20 12:00:20.814 luup.variable_watch:3: callback=variableWatchCallback, watching=6.urn:micasaverde-com:serviceId:SecuritySensor1.Tripped
2016-10-20 12:00:20.815 luup.variable_watch:3: callback=variableWatchCallback, watching=6.urn:micasaverde-com:serviceId:HaDevice1.BatteryLevel
2016-10-20 12:00:20.816 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [] now: [] #hooks:0
2016-10-20 12:00:20.816 luup_log:3: ALTUI: Wkflow - enableWorkflows(3,0)
2016-10-20 12:00:20.816 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: [] now: #hooks:0
2016-10-20 12:00:20.816 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: [] now: #hooks:0
2016-10-20 12:00:20.816 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsVariableBag was: now: #hooks:0
2016-10-20 12:00:20.817 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: now: [] #hooks:0
2016-10-20 12:00:20.817 luup.register_handler:3: global_function_name=myALTUI_Handler, request=ALTUI_Handler
2016-10-20 12:00:20.827 luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunLua
2016-10-20 12:00:20.828 luup.register_handler:0: global_function_name=ALTUI_LuaRunHandler, request=ALTUI_LuaRunHandler
2016-10-20 12:00:20.832 luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunLua
2016-10-20 12:00:20.833 luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was: now: [] #hooks:0
2016-10-20 12:00:20.833 luup.set_failure:3: status = 0
2016-10-20 12:00:20.833 luup.variable_set:3: 3.urn:micasaverde-com:serviceId:HaDevice1.CommFailure was: 0 now: 0 #hooks:0
2016-10-20 12:00:20.833 luup.variable_set:3: 3.urn:micasaverde-com:serviceId:HaDevice1.CommFailureTime was: 0 now: 0 #hooks:0
2016-10-20 12:00:20.833 luup_log:3: ALTUI: startup completed
2016-10-20 12:00:22.370 openLuup.server:: request completed (20052 bytes, 2 chunks, 1573 ms) tcp{client}: 0x634458
2016-10-20 12:00:22.988 openLuup.server:: receive error: closed tcp{client}: 0x634458
2016-10-20 12:00:23.101 openLuup.server:: new client connection: tcp{client}: 0x6770e0
2016-10-20 12:00:23.186 openLuup.server:: GET /data_request?id=user_data&output_format=json&DataVersion=555749258&
=1476989916818 HTTP/1.0 tcp{client}: 0x6770e0
2016-10-20 12:00:23.246 openLuup.server:: request completed (45551 bytes, 3 chunks, 59 ms) tcp{client}: 0x6770e0
2016-10-20 12:00:24.039 openLuup.server:: receive error: closed tcp{client}: 0x6770e0
2016-10-20 12:00:26.144 openLuup.server:: new client connection: tcp{client}: 0x639660
2016-10-20 12:00:26.228 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=990019477&Timeout=60&MinimumDelay=1500&=1476989916819 HTTP/1.0 tcp{client}: 0x639660
2016-10-20 12:00:29.618 openLuup.server:: new client connection: tcp{client}: 0x56a5d0
2016-10-20 12:00:29.703 openLuup.server:: GET /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=tail%20LuaUPnP.log&
=1476989916820 HTTP/1.0 tcp{client}: 0x56a5d0
2016-10-20 12:00:29.715 openLuup.server:: request completed (1209 bytes, 1 chunks, 11 ms) tcp{client}: 0x56a5d0
2016-10-20 12:00:30.096 openLuup.server:: receive error: closed tcp{client}: 0x56a5d0
2016-10-20 12:00:46.624 openLuup.server:: new client connection: tcp{client}: 0x6d6870
2016-10-20 12:00:46.710 openLuup.server:: GET /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=ls&=1476989916821 HTTP/1.0 tcp{client}: 0x6d6870
2016-10-20 12:00:46.724 openLuup.server:: request completed (762 bytes, 1 chunks, 14 ms) tcp{client}: 0x6d6870
2016-10-20 12:00:47.058 openLuup.server:: receive error: closed tcp{client}: 0x6d6870
2016-10-20 12:01:02.172 openLuup.server:: new client connection: tcp{client}: 0x64b580
2016-10-20 12:01:02.257 openLuup.server:: GET /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=tail%20LuaUPnP.log&
=1476989916822 HTTP/1.0 tcp{client}: 0x64b580
2016-10-20 12:01:02.263 openLuup.server:: request completed (1184 bytes, 1 chunks, 6 ms) tcp{client}: 0x64b580
2016-10-20 12:01:02.438 openLuup.server:: receive error: closed tcp{client}: 0x64b580
2016-10-20 12:01:17.145 openLuup.server:: new client connection: tcp{client}: 0x662fb0
2016-10-20 12:01:17.229 openLuup.server:: GET /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=tail%20-n%2050%20%2Fvar%2Flog%2Fcmh%2FLuaUPnP.log&=1476989916823 HTTP/1.0 tcp{client}: 0x662fb0
2016-10-20 12:01:17.244 openLuup.server:: request completed (2 bytes, 1 chunks, 15 ms) tcp{client}: 0x662fb0
2016-10-20 12:01:17.334 openLuup.server:: receive error: closed tcp{client}: 0x662fb0
2016-10-20 12:01:26.145 openLuup.server:: receive error: closed tcp{client}: 0x639660
2016-10-20 12:01:26.648 openLuup.server:: error ‘closed’ sending 164 bytes to tcp{client}: 0x639660
2016-10-20 12:01:26.649 openLuup.server:: …only 0 bytes sent
2016-10-20 12:01:26.649 openLuup.server:: error ‘closed’ sending 5 bytes to tcp{client}: 0x639660
2016-10-20 12:01:26.649 openLuup.server:: …only 0 bytes sent
2016-10-20 12:01:26.649 openLuup.server:: error ‘closed’ sending 1361 bytes to tcp{client}: 0x639660
2016-10-20 12:01:26.649 openLuup.server:: …only 0 bytes sent
2016-10-20 12:01:26.649 openLuup.server:: error ‘closed’ sending 2 bytes to tcp{client}: 0x639660
2016-10-20 12:01:26.649 openLuup.server:: …only 0 bytes sent
2016-10-20 12:01:26.649 openLuup.server:: error ‘closed’ sending 5 bytes to tcp{client}: 0x639660
2016-10-20 12:01:26.649 openLuup.server:: …only 0 bytes sent
2016-10-20 12:01:26.649 openLuup.server:: request completed (1361 bytes, 1 chunks, 60421 ms) tcp{client}: 0x639660
2016-10-20 12:01:27.236 openLuup.server:: new client connection: tcp{client}: 0x55d778
2016-10-20 12:01:27.325 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=990019477&Timeout=60&MinimumDelay=1500&
=1476989916824 HTTP/1.0 tcp{client}: 0x55d778
2016-10-20 12:01:32.017 openLuup.server:: new client connection: tcp{client}: 0x6e2c80
2016-10-20 12:01:32.435 openLuup.server:: GET /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=tail%20-n%20500%20LuaUPnP.log&_=1476989916825 HTTP/1.0 tcp{client}: 0x6e2c80

This looks odd. I don’t understand why there are so many receive errors. Is there anything unusual about your system / network? Which browser are you using? Have you tried a different one?

From the log, all looks to be well. It seems like you only have the one ZWave device and no other plugins, apart from the basic ones, installed. This should simply work. How did you install the system? We’re there any problems showing then?

I might suggest you simply perform a reset of the openLuup system and run it for a while without the ZWay plugin. The less you have running the easier it may be to track this down. I’ve really not seen this behaviour before.

I think I have a very plain system and network, nothing unusual, no vlan, weird routing etc. Of course something could be broken that I’m not aware of. But it’s a Raspberry 3 with the UZB loaded and the software installed.

I’m using Chrome. Although until now, I have always been running it remotely, not directly on the Raspberry Pi. I followed your advice and disabled the Zway plugin, shut down and restarted openLuup, and am trying the local browser. So far I don’t see any errors. I’ll try adding in Zway in the morning to see if that is related or not.

How did I install? First I got Zway installed and working. Then loaded the developer version of openLuup from github and started it up and enabled the Zway plugin. Nothing looked amiss when I did this. Updated ALTUI to the latest and started using it. Some of the setup is not obvious so I could easily have made a mistake along the way.

Ran all night with no errors without the Zway plugin. Added the Zway plugin and the errors are back. I can’t say that the issue is necessarily with Zway; since there isn’t much happening without it, it’s possible that it is simply exposing some other problem by being enabled. Anyway, I’m a bit stuck on this. Any suggestions for further debug? Thanks.

Can you PM me the user_data.json file for the failing system?

I should say that I’ve developed and tested this system on a Pi with a Razberry board, not with the UZB. You did buy a licence for the UZB in addition to the hardware? It does work as expected if you address it directly with either the smarthome or expert UI? What IP address have you configured?

Yes, I did buy the license for the UZB. But the problem was with me. I had some errors in an attempt to watch a variable, and I have an incomplete installation. So more work to do but I think I’m on the right track now.

Still have this issue, but I have a little more information:

  • The issue never occurs if I use Chrome on the Raspberry Pi directly
  • The issue is there every time I use a browser on the local LAN but not on the Pi
  • The issue is there for both Wifi and hard-wired LAN connections

If anyone has an idea on how to troubleshoot this further I would appreciate it.

Remind us which hardware/software you are running this on…?

Also, exactly how did you install the Z-Wave.me ZWay server (ie. not my ZWay openLuup plugin.)

This is on a Raspberry Pi 3 with latest updates (believe this is Raspbian Jessie with PIXEL). Installed the Z-way server software via the instructions on the zwave.me page: “wget -q -O - razberry.z-wave.me/install | sudo bash”. Running on UZB stick with purchased license.

This is all very odd…

It sounds like you have the Z-way server instance up and running if you were able to include a device (original post). Have you attempted to observe the network within Google Chrome (on the LAN not as a localhost) using the dev console (F12) / Network and see if anything is logged there that would help us.

thanks - I’ll give that a try and report back. Note that the Pi/Zway/OpenLuup is basically working. ALTUI is up and running and I have scenes executing and 4 devices functioning. It’s mostly there, but something isn’t quite right. Maybe I have a software version incompatibility. Anyway, I’ll try the Chrome network debug and see if I can find anything there.

Not that this should really matter but I’m curious. What version of Z-way server are you running (ip:8083/expert) ? With the URL you provided, I’m wondering if you’re running 2.2.3 (stable) or one of the release candidates.I also see they posted a 2.3.0 release candidate. Would love to see a maintenance release to correct 2.2.4. I digress …

I’m using 2.2.4. No major issues as far as I can tell - at least for my limited system with the UZB. I think the problem I have is with LAN access to the OpenLuup server, not from the OpenLuup server to the Zway. When OpenLuup is running without connections from Altui it runs fine and I have no errors in the log. I tried Imperihome and it connected and showed similar receive error messages. So I don’t think this is related to Altui.

Glad to hear you’re not running a release candidate. It looks as if you ruled out my second though which was a saturated system due to a shared bus for LAN and USB (you indicated WiFi didn’t alleviate the issue). Curious to see what Chrome debugger tells us…

We could always move testing to an Oracle Virtual running Debian Jessie with the UZB mounted.

Back to this issue. I’ve learned that the receive errors are happening when the browser does a status request. Here’s a sample:

http://:3480/data_request?id=lu_status2&output_format=json&DataVersion=356762269&Timeout=60&MinimumDelay=1500&_=NNNNN

This can take up to 20 seconds. Chrome finally sees the data and says the response is 200 (I believe that is good), yet at that very moment I see the error logged on the openLuup side. If I grab the request above and reload it in the browser, it sometimes takes up to 20 seconds, but after a repeat or two, it becomes very quick.

Any ideas?

This is standard, and correct, behaviour. openLuup will not respond until something in the system has changed. The MinimumDelay parameter of 1500 means that it will anyway delay 1.5 seconds. The Timeout parameter of 60 means that it will respond after a minute even if nothing happens.

Try that request without those two parameters, and the response should be immediate.