openLuup: Sonos

Plugins & Plugin Development openLuup
#1

This has been a topic that has been discussed in the past (AV Plugins) but I felt this deserved it’s own thread for community discussion/involvement. My production system is an x86 running OpenWrt/openLuup. This system has one Sonos running locally and works well playing music. If I add another Sonos, both stop working all together (details are left in the previous AV discussion). This was never resolved nor did I pursue it further since a workaround was simply utilizing the bridge to control the remaining devices.

Recently I attempted to test the Sonos plugin (v1.4) again using the latest openLuup development branch. The systems were both an x86 and Odroid XU4 running Debian Jessie 8.3. No other plugins were installed. Out-the-gate, a failure occurs and the plugin ceases to function. Obviously on a Vera, this plugin works perfectly.

[hr]

x86

2016-03-29 16:14:51.436   :: openLuup STARTUP :: 
2016-03-29 16:14:51.436   openLuup.init::      version 2016.02.25  @akbooer
2016-03-29 16:14:51.458   openLuup.scheduler:: version 2016.03.01  @akbooer
2016-03-29 16:14:51.458   openLuup.wsapi::     version 2016.03.05  @akbooer
2016-03-29 16:14:51.458   openLuup.server::    version 2016.03.20  @akbooer
2016-03-29 16:14:51.461   openLuup.plugins::   version 2016.03.05  @akbooer
2016-03-29 16:14:51.464   openLuup.scenes::    version 2016.03.11  @akbooer
2016-03-29 16:14:51.465   openLuup.chdev::     version 2016.02.15  @akbooer
2016-03-29 16:14:51.466   openLuup.io:0:        version 2016.02.15  @akbooer
2016-03-29 16:14:51.466   openLuup.luup:0:      version 2016.03.01  @akbooer
2016-03-29 16:14:51.469   openLuup.rooms::     version 2015.10.15  @akbooer
2016-03-29 16:14:51.469   openLuup.requests::  version 2016.03.11  @akbooer
2016-03-29 16:14:51.469   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-29 16:14:51.469   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-29 16:14:51.469   openLuup.init:: loading configuration user_data.json
2016-03-29 16:14:51.469   openLuup.init:: loading user_data json...
2016-03-29 16:14:51.483   openLuup.init:: loading rooms...
2016-03-29 16:14:51.485   openLuup.init:: ...room loading completed
2016-03-29 16:14:51.485   openLuup.init:: loading devices...
2016-03-29 16:14:51.485   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-29 16:14:51.486   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-29 16:14:51.503   luup.create_device:: [3] D_ALTUI.xml / I_ALTUI.xml / D_ALTUI_UI7.json
2016-03-29 16:14:51.505   luup.create_device:: [4] D_openLuupExtensions.xml / I_openLuupExtensions.xml / D_openLuupExtensions.json
2016-03-29 16:14:51.570   luup.create_device:: [6] D_Sonos1.xml / I_Sonos1.xml / D_Sonos1.json
2016-03-29 16:14:51.570   openLuup.init:: loading scenes...
2016-03-29 16:14:51.570   openLuup.init:: number of scenes = 0
2016-03-29 16:14:51.570   openLuup.init:: ...scene loading completed
2016-03-29 16:14:51.570   openLuup.init:: loading installed plugin info...
2016-03-29 16:14:51.570   openLuup.init:: ...user_data loading completed
2016-03-29 16:14:51.570   openLuup.init:: running _openLuup_STARTUP_
2016-03-29 16:14:51.570   openLuup.init:: init phase completed
2016-03-29 16:14:51.570   openLuup.server:: starting HTTP server on 172.16.5.200:3480 tcp{server}: 0xc79728
2016-03-29 16:14:51.570   openLuup.scheduler:: starting
2016-03-29 16:14:51.570   openLuup.scheduler:: [3] device startup
2016-03-29 16:14:51.570   luup_log:3: ALTUI: initstatus(3) starting version: v1.28
2016-03-29 16:14:51.570   openLuup.scheduler:: [3] device startup completed: status=nil, msg=nil, name=nil
2016-03-29 16:14:51.570   openLuup.scheduler:: [4] device startup
2016-03-29 16:14:51.570   luup.register_handler:4: global_function_name=HTTP_Extensions, request=version
2016-03-29 16:14:51.570   luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine1 was: Uptime 0 now: Uptime 0 #hooks:0
2016-03-29 16:14:51.570   luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine2 was:  now:  #hooks:0
2016-03-29 16:14:51.570   openLuup.scheduler:: [4] device startup completed: status=nil, msg=synchronising in 68.4 seconds, name=openLuup:Extensions
2016-03-29 16:14:51.570   openLuup.scheduler:: [6] device startup
2016-03-29 16:14:51.570   luup_log:6: Sonos: #6 starting up with id Sonos
2016-03-29 16:14:51.570   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-29 16:14:51.577   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-29 16:14:51.577   openLuup.scheduler:: [6] device startup completed: status=nil, msg=nil, name=nil
2016-03-29 16:14:51.680   openLuup.server:: new client connection: tcp{client}: 0xc7e4e8
2016-03-29 16:14:51.681   openLuup.server:: /favicon.ico tcp{client}: 0xc7e4e8
2016-03-29 16:14:51.681   openLuup.HTTP.FILE:: file not found:favicon.ico
2016-03-29 16:14:51.682   openLuup.server:: request completed (0 bytes, 0 chunks, 0 ms) tcp{client}: 0xc7e4e8
2016-03-29 16:14:51.930   openLuup.server:: new client connection: tcp{client}: 0xc83948
2016-03-29 16:14:52.763   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=285998431&Timeout=60&MinimumDelay=1500&_=1459285992967 tcp{client}: 0xc7e4e8
2016-03-29 16:14:52.763   luup_log:3: ALTUI: startupDeferred, called on behalf of device:3
2016-03-29 16:14:52.763   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.LocalHome was:  now:  #hooks:0
2016-03-29 16:14:52.766   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Version was: v1.28 now: v1.28 #hooks:0
2016-03-29 16:14:52.768   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.DataStorageProviders was: {"emoncms":{"url":"","callback":"sendValueToStorage_emoncms","parameters":[{"default":1,"type":"number","key":"nodeid","label":"Node ID"},{"type":"number","key":"feedid","label":"Feed ID"},{"type":"text","key":"inputkey","label":"Input Key name"},{"type":"text","key":"readwritekey","label":"Read/Write API Key"},{"type":"url","key":"graphicurl","label":"Graphic Url","ifheight":460,"default":"http://emoncms.org/vis/editrealtime?feedid={1}&embed=1&apikey={3}"}]},"thingspeak":{"url":"","callback":"sendValueToStorage_thingspeak","parameters":[{"type":"number","key":"channelid","label":"Channel ID"},{"type":"text","key":"readkey","label":"Read API Key"},{"type":"text","key":"writekey","label":"Write API Key"},{"default":1,"type":"number","key":"fieldnum","label":"Field Number"},{"default":"//api.thingspeak.com/channels/{0}/charts/{3}?key={1}&width=450&height=260&results=60&dynamic=true","type":"url","key":"graphicurl","label":"Graphic Url"}]}} now: {"emoncms":{"url":"","callback":"sendValueToStorage_emoncms","parameters":[{"key":"nodeid","type":"number","default":1,"label":"Node ID"},{"type":"number","key":"feedid","label":"Feed ID"},{"type":"text","key":"inputkey","label":"Input Key name"},{"type":"text","key":"readwritekey","label":"Read/Write API Key"},{"type":"url","key":"graphicurl","label":"Graphic Url","ifheight":460,"default":"http://emoncms.org/vis/editrealtime?feedid={1}&embed=1&apikey={3}"}]},"thingspeak":{"url":"","callback":"sendValueToStorage_thingspeak","parameters":[{"type":"number","key":"channelid","label":"Channel ID"},{"type":"text","key":"readkey","label":"Read API Key"},{"type":"text","key":"writekey","label":"Write API Key"},{"default":1,"type":"number","key":"fieldnum","label":"Field Number"},{"default":"//api.thingspeak.com/channels/{0}/charts/{3}?key={1}&width=450&height=260&results=60&dynamic=true","type":"url","key":"graphicurl","label":"Graphic Url"}]}} #hooks:0
2016-03-29 16:14:52.770   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.DataStorageProviders was: {"emoncms":{"url":"","callback":"sendValueToStorage_emoncms","parameters":[{"key":"nodeid","type":"number","default":1,"label":"Node ID"},{"type":"number","key":"feedid","label":"Feed ID"},{"type":"text","key":"inputkey","label":"Input Key name"},{"type":"text","key":"readwritekey","label":"Read/Write API Key"},{"type":"url","key":"graphicurl","label":"Graphic Url","ifheight":460,"default":"http://emoncms.org/vis/editrealtime?feedid={1}&embed=1&apikey={3}"}]},"thingspeak":{"url":"","callback":"sendValueToStorage_thingspeak","parameters":[{"type":"number","key":"channelid","label":"Channel ID"},{"type":"text","key":"readkey","label":"Read API Key"},{"type":"text","key":"writekey","label":"Write API Key"},{"default":1,"type":"number","key":"fieldnum","label":"Field Number"},{"default":"//api.thingspeak.com/channels/{0}/charts/{3}?key={1}&width=450&height=260&results=60&dynamic=true","type":"url","key":"graphicurl","label":"Graphic Url"}]}} now: {"emoncms":{"url":"","callback":"sendValueToStorage_emoncms","parameters":[{"default":1,"type":"number","key":"nodeid","label":"Node ID"},{"type":"number","key":"feedid","label":"Feed ID"},{"type":"text","key":"inputkey","label":"Input Key name"},{"type":"text","key":"readwritekey","label":"Read/Write API Key"},{"type":"url","key":"graphicurl","label":"Graphic Url","ifheight":460,"default":"http://emoncms.org/vis/editrealtime?feedid={1}&embed=1&apikey={3}"}]},"thingspeak":{"url":"","callback":"sendValueToStorage_thingspeak","parameters":[{"type":"number","key":"channelid","label":"Channel ID"},{"type":"text","key":"readkey","label":"Read API Key"},{"type":"text","key":"writekey","label":"Write API Key"},{"default":1,"type":"number","key":"fieldnum","label":"Field Number"},{"default":"//api.thingspeak.com/channels/{0}/charts/{3}?key={1}&width=450&height=260&results=60&dynamic=true","type":"url","key":"graphicurl","label":"Graphic Url"}]}} #hooks:0
2016-03-29 16:14:52.770   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToSend was:  now:  #hooks:0
2016-03-29 16:14:52.770   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.RemoteVariablesToWatch was:  now:  #hooks:0
2016-03-29 16:14:52.770   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was:  now:  #hooks:0
2016-03-29 16:14:52.770   luup_log:3: ALTUI: Wkflow - enableWorkflows(3,0)
2016-03-29 16:14:52.770   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was:  now:  #hooks:0
2016-03-29 16:14:52.770   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: [] now:  #hooks:0
2016-03-29 16:14:52.771   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was:  now: [] #hooks:0
2016-03-29 16:14:52.771   luup.register_handler:3: global_function_name=myALTUI_Handler, request=ALTUI_Handler
2016-03-29 16:14:52.775   luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunLua 
2016-03-29 16:14:52.776   luup.register_handler:0: global_function_name=ALTUI_LuaRunHandler, request=ALTUI_LuaRunHandler
2016-03-29 16:14:52.777   luup.set_failure:3: status = 0
2016-03-29 16:14:52.777   luup_log:3: ALTUI: startup completed
2016-03-29 16:14:52.777   luup_log:6: Sonos: UPnP proxy event identified - API version 
2016-03-29 16:14:52.778   openLuup.context_switch::  ERROR: ./L_Sonos1.lua:947: attempt to compare number with nil
2016-03-29 16:14:52.778   luup.delay_callback:: function: 0xaadd40 ERROR: ./L_Sonos1.lua:947: attempt to compare number with nil

Odroid (filtered log)

2016-03-29 19:24:13.995   luup.create_device:: [39] D_Sonos1.xml / I_Sonos1.xml / D_Sonos1.json
2016-03-29 19:24:16.815   luup_log:39: Sonos: #39 starting up with id Sonos
2016-03-29 19:24:16.815   luup.variable_set:39: 39.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-29 19:24:16.914   luup_log:39: Sonos: debug: sonosStartup: Vera IP Address=10.0.4.140
2016-03-29 19:24:16.978   luup.variable_set:39: 39.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-29 19:24:18.065   luup_log:39: Sonos: debug: deferredSonosStartup: start 39
2016-03-29 19:24:18.074   luup_log:39: Sonos: UPnP proxy event identified - API version 
2016-03-29 19:24:18.076   openLuup.context_switch::  ERROR: ./L_Sonos1.lua:947: attempt to compare number with nil
2016-03-29 19:24:18.077   luup.delay_callback:: function: 0x8ed48 ERROR: ./L_Sonos1.lua:947: attempt to compare number with nil
2016-03-29 19:25:33.236   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=cat%20%2Fvar%2Flog%2Fcmh%2FLuaUPnP.log%20%7C%20grep%20%22Sonos%22&_=1459300591688 tcp{client}: 0x4ee980

[hr]

943 -- WeMo plugin contrib
944 -- proxyVersionAtLeast(n)
945 -- Returns true if the proxy is running and is at least version n.
946  function proxyVersionAtLeast(n)
947    if (ProxyApiVersion and tonumber(ProxyApiVersion:match("^(%d+)")) >= n) then
948        return true
949    end
950    return false
951  end

[hr]

an error occurred while displaying the javascript tab. devid: 0-6 err:unsafe.replace is not a function
stack:TypeError: unsafe.replace is not a function
    at Sonos_escapeHtmlSpecialChars (J_Sonos1.js:904:5)
    at Sonos_showHelp (J_Sonos1.js:417:20)
    at eval (eval at _deviceDrawControlPanelJSTab (http://172.16.5.200:3480/J_ALTUI_uimgr.js:3660:41), :1:1)
    at _deviceDrawControlPanelJSTab (http://172.16.5.200:3480/J_ALTUI_uimgr.js:3660:17)
    at _deviceDrawControlPanelOneTabContent (http://172.16.5.200:3480/J_ALTUI_uimgr.js:4077:7)
    at _displayActiveDeviceTab (http://172.16.5.200:3480/J_ALTUI_uimgr.js:4103:4)
    at HTMLAnchorElement. (http://172.16.5.200:3480/J_ALTUI_uimgr.js:6342:4)
    at HTMLDivElement.n.event.dispatch (http://ajax.googleapis.com/ajax/libs/jquery/1.12.0/jquery.min.js:3:12344)
    at HTMLDivElement.r.handle (http://ajax.googleapis.com/ajax/libs/jquery/1.12.0/jquery.min.js:3:9071)
    at Object.n.event.trigger (http://ajax.googleapis.com/ajax/libs/jquery/1.12.0/jquery.min.js:3:11471)

[hr]

I’m looking for feedback (good, bad or otherwise) regarding the use of this plugin within openLuup. If you’re unable to get this plugin working locally, please provide details (e.g detailed log data, number of Sonos systems, environment etc.). Providing this information will help in identifying if it’s time to reach out to the developer of the Sonos plugin and see if that individual will assist.

Thanks in advance…

#2

OK, I know this has been a bone of contention for some time. Let’s try and fix it…

My startup log looks like this for two Sonos systems:

2016-03-30 14:49:19.945   openLuup.scheduler:: [9] device startup
2016-03-30 14:49:19.953   luup_log:9: Sonos: #9 starting up with id Sonos
2016-03-30 14:49:19.967   luup.variable_set:9: 9.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-30 14:49:20.541   luup.variable_set:9: 9.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-30 14:49:20.547   openLuup.scheduler:: [9] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 14:49:20.551   openLuup.scheduler:: [70] device startup
2016-03-30 14:49:20.558   luup_log:70: Sonos: #70 starting up with id
2016-03-30 14:49:20.565   luup.variable_set:70: 70.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-30 14:49:21.096   luup.variable_set:70: 70.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-30 14:49:21.100   openLuup.scheduler:: [70] device startup completed: status=nil, msg=nil, name=nil

[...]

2016-03-30 14:49:22.610   luup_log:9: Sonos: error: Cannot contact UPnP event proxy: connection refused
2016-03-30 14:49:22.613   luup_log:9: Sonos: UPnP proxy event identified - API version
2016-03-30 14:49:23.510   luup.variable_set:9: 9.urn:upnp-org:serviceId:ContentDirectory.FavoritesRadios was: EMPTY now: R:0/0/0@BBC Radio 4 LW 198 (Public Radio) #hooks:0
2016-03-30 14:49:23.571   luup.variable_set:9: 9.urn:upnp-org:serviceId:ContentDirectory.Favorites was: FV:2/3@BBC Radio 4 93.5 (National News) now: FV:2/3@BBC Radio 4 93.5$
FV:2/2@BBC Radio 4 Extra (Comedy)
FV:2/4@Classic FM
 #hooks:0
2016-03-30 14:49:23.576   luup.variable_set:9: 9.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1597549956 now: 1459345763 #hooks:0

[...]

2016-03-30 14:49:26.028   luup_log:70: Sonos: error: Cannot contact UPnP event proxy: connection refused
2016-03-30 14:49:26.032   luup_log:70: Sonos: UPnP proxy event identified - API version
2016-03-30 14:49:26.850   luup.variable_set:70: 70.urn:upnp-org:serviceId:ContentDirectory.FavoritesRadios was: EMPTY now: R:0/0/0@BBC Radio 4 LW 198 (Public Radio)
 #hooks:0
2016-03-30 14:49:26.937   luup.variable_set:70: 70.urn:upnp-org:serviceId:ContentDirectory.Favorites was: FV:2/3@BBC Radio 4 93.5 (National News) now: FV:2/3@BBC Radio 4 93$
FV:2/2@BBC Radio 4 Extra (Comedy)
FV:2/4@Classic FM
 #hooks:0
2016-03-30 14:49:26.941   luup.variable_set:70: 70.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1597622229 now: 1459345766 #hooks:0
2016-03-30 14:49:27.157   luup.variable_set:70: 70.urn:micasaverde-com:serviceId:Sonos1.SonosServicesKeys was: 254=SA_RINCON65031_ now: 254=SA_RINCON65031_
 #hooks:0
2016-03-30 14:49:27.168   luup.variable_set:70: 70.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1459345766 now: 1459345767 #hooks:0

I’ve attached a snapshot of the attributes and the settings from AltUI. Note that I do NOT have the discovery patch installed, I do not run the UPnP proxy, and also that in my original startup.lua configuration of the device I explicitly set the IP using luup.ip_set()

For your error, the Lua code on line 947 can certainly generate that if [tt]ProxyApiVersion[/tt] is nil. It should be rewritten so, to avoid this:

  function proxyVersionAtLeast(n)
    return tonumber((ProxyApiVersion or ''):match("^(%d+)") or 0) >= n
  end

However, we need to discover why it’s not defined in the first place. I can only assume that you are, in fact, running the proxy?

#3

Your log entry is interesting as I don’t see that on either of my test systems. Let me make an adjustment to the function and see what the result is…

2016-03-30 14:49:22.610   luup_log:9: Sonos: error: Cannot contact UPnP event proxy: connection refused
#4

Interesting, running a small test against getProxyApiVersion, the result is “nil” and the code is “closed” on both my x86/Debian @ work and my rPi3/Debian @ home. So it makes sense why you’re saying I’m running UPnP… But I can’t seem to find out where that is… All tests (so far) indicated I’m not but this code says otherwise and your log entries say your not. Ugh !

Edit: Attached screen shot of Sonos Play1 @ home… This device was installed via Lua test setting the IP…

    if (request == nil and code == "timeout") then
        -- Proxy may be busy.
        warning("Temporarily cannot communicate with proxy")
        return nil
    elseif (request == nil and code ~= "closed") then
        -- Proxy not running.
        error("Cannot contact UPnP event proxy: " .. code)
        return ""
    else
        -- Proxy is running, note its version number.
        ProxyApiVersion = table.concat(t)
        return ProxyApiVersion
    end

Since I’m unable to SSH into my system at home (blocked by office firewall), I ran the adjusted function (proxyVersionAtLeast) on my x86 here and it’s starting clean (thanks for that). Obviously I don’t have a Sonos here so I’m cheating a bit and I’m limited to what I can do.

2016-03-30 11:32:22.202   :: openLuup STARTUP :: 
2016-03-30 11:32:22.202   openLuup.init::      version 2016.02.25  @akbooer
2016-03-30 11:32:22.221   openLuup.scheduler:: version 2016.03.01  @akbooer
2016-03-30 11:32:22.222   openLuup.wsapi::     version 2016.03.05  @akbooer
2016-03-30 11:32:22.222   openLuup.server::    version 2016.03.20  @akbooer
2016-03-30 11:32:22.224   openLuup.plugins::   version 2016.03.05  @akbooer
2016-03-30 11:32:22.226   openLuup.scenes::    version 2016.03.11  @akbooer
2016-03-30 11:32:22.228   openLuup.chdev::     version 2016.02.15  @akbooer
2016-03-30 11:32:22.229   openLuup.io:0:        version 2016.02.15  @akbooer
2016-03-30 11:32:22.229   openLuup.luup:0:      version 2016.03.01  @akbooer
2016-03-30 11:32:22.231   openLuup.rooms::     version 2015.10.15  @akbooer
2016-03-30 11:32:22.231   openLuup.requests::  version 2016.03.11  @akbooer
2016-03-30 11:32:22.232   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-30 11:32:22.232   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-30 11:32:22.232   openLuup.init:: loading configuration user_data.json
2016-03-30 11:32:22.232   openLuup.init:: loading user_data json...
2016-03-30 11:32:22.245   openLuup.init:: loading rooms...
2016-03-30 11:32:22.245   openLuup.init:: ...room loading completed
2016-03-30 11:32:22.245   openLuup.init:: loading devices...
2016-03-30 11:32:22.245   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-30 11:32:22.245   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-30 11:32:22.258   luup.create_device:: [3] D_ALTUI.xml / I_ALTUI.xml / D_ALTUI_UI7.json
2016-03-30 11:32:22.259   luup.create_device:: [4] D_openLuupExtensions.xml / I_openLuupExtensions.xml / D_openLuupExtensions.json
2016-03-30 11:32:22.321   luup.create_device:: [6] D_Sonos1.xml / I_Sonos1.xml / D_Sonos1.json
2016-03-30 11:32:22.321   openLuup.init:: loading scenes...
2016-03-30 11:32:22.321   openLuup.init:: number of scenes = 0
2016-03-30 11:32:22.321   openLuup.init:: ...scene loading completed
2016-03-30 11:32:22.321   openLuup.init:: loading installed plugin info...
2016-03-30 11:32:22.321   openLuup.init:: ...user_data loading completed
2016-03-30 11:32:22.321   openLuup.init:: running _openLuup_STARTUP_
2016-03-30 11:32:22.321   openLuup.init:: init phase completed
2016-03-30 11:32:22.321   openLuup.server:: starting HTTP server on 172.16.5.148:3480 tcp{server}: 0x2622d78
2016-03-30 11:32:22.321   openLuup.scheduler:: starting
2016-03-30 11:32:22.321   openLuup.scheduler:: [3] device startup
2016-03-30 11:32:22.321   luup_log:3: ALTUI: initstatus(3) starting version: v1.28
2016-03-30 11:32:22.321   openLuup.scheduler:: [3] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 11:32:22.321   openLuup.scheduler:: [4] device startup
2016-03-30 11:32:22.321   luup.register_handler:4: global_function_name=HTTP_Extensions, request=version
2016-03-30 11:32:22.321   luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine1 was: Uptime 0.02 days now: Uptime 0 #hooks:0
2016-03-30 11:32:22.321   luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine2 was: Memory 2.4 Mb,  CPU 0 % now:  #hooks:0
2016-03-30 11:32:22.321   openLuup.scheduler:: [4] device startup completed: status=nil, msg=synchronising in 97.7 seconds, name=openLuup:Extensions
2016-03-30 11:32:22.321   openLuup.scheduler:: [6] device startup
2016-03-30 11:32:22.321   luup_log:6: Sonos: #6 starting up with id Sonos
2016-03-30 11:32:22.321   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-30 11:32:22.328   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-30 11:32:22.328   openLuup.scheduler:: [6] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 11:32:22.339   openLuup.server:: new client connection: tcp{client}: 0x2627c18
2016-03-30 11:32:22.340   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=353506525&Timeout=60&MinimumDelay=1500&_=1459353515660 tcp{client}: 0x2627c18
2016-03-30 11:32:22.586   openLuup.server:: new client connection: tcp{client}: 0x262cfd8
2016-03-30 11:32:23.590   luup_log:3: ALTUI: startupDeferred, called on behalf of device:3
2016-03-30 11:32:23.590   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.LocalHome was:  now:  #hooks:0
2016-03-30 11:32:23.592   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Version was: v1.28 now: v1.28 #hooks:0

{removed}


2016-03-30 11:32:23.602   luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunLua 
2016-03-30 11:32:23.602   luup.register_handler:0: global_function_name=ALTUI_LuaRunHandler, request=ALTUI_LuaRunHandler
2016-03-30 11:32:23.603   luup.set_failure:3: status = 0
2016-03-30 11:32:23.603   luup_log:3: ALTUI: startup completed
2016-03-30 11:32:23.604   luup_log:6: Sonos: UPnP proxy event identified - API version 
2016-03-30 11:32:24.120   openLuup.server:: request completed (19815 bytes, 2 chunks, 1780 ms) tcp{client}: 0x2627c18
2016-03-30 11:32:24.127   openLuup.server:: /data_request?id=user_data&output_format=json&DataVersion=353506208&_=1459353515661 tcp{client}: 0x2627c18
2016-03-30 11:32:24.150   openLuup.server:: request completed (43775 bytes, 3 chunks, 23 ms) tcp{client}: 0x2627c18
2016-03-30 11:32:26.159   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=355542434&Timeout=60&MinimumDelay=1500&_=1459353515662 tcp{client}: 0x2627c18
2016-03-30 11:32:28.246   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=tail%20-n%20500%20%2Fetc%2Fcmh-ludl%2FLuaUPnP.log&_=1459353515663 tcp{client}: 0x262cfd8
2016-03-30 11:32:28.246   luup_log:3: ALTUI: ALTUI_Handler: parameters is: {"command":"oscommand","oscommand":"tail -n 500 /etc/cmh-ludl/LuaUPnP.log","_":"1459353515663"}
#5

I believe it has to do with localhost, for example this results in nil/closed which acts like a proxy is running

    local t = {}
    local request, code = http.request({
        url = "http://localhost:2529/version",
        create = sock,
        sink = ltn12.sink.table(t)
    })

And this results in nil/connection refused…

    local t = {}
    local request, code = http.request({
        url = "http://127.0.0.1:2529/version",
        create = sock,
        sink = ltn12.sink.table(t)
    })

Pinging localhost results in…

root@Test:/etc/dhcp# ping -c 2 localhost
PING localhost (127.0.0.1) 56(84) bytes of data.
64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.044 ms
64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.054 ms

--- localhost ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 0.044/0.049/0.054/0.005 ms

And restoring the Lua file (albeit patching localhost with 127.0.0.1) yields this…

2016-03-30 13:41:22.628   :: openLuup STARTUP :: 
2016-03-30 13:41:22.628   openLuup.init::      version 2016.02.25  @akbooer
2016-03-30 13:41:22.652   openLuup.scheduler:: version 2016.03.01  @akbooer
2016-03-30 13:41:22.653   openLuup.wsapi::     version 2016.03.05  @akbooer
2016-03-30 13:41:22.653   openLuup.server::    version 2016.03.20  @akbooer
2016-03-30 13:41:22.656   openLuup.plugins::   version 2016.03.05  @akbooer
2016-03-30 13:41:22.659   openLuup.scenes::    version 2016.03.11  @akbooer
2016-03-30 13:41:22.660   openLuup.chdev::     version 2016.02.15  @akbooer
2016-03-30 13:41:22.661   openLuup.io:0:        version 2016.02.15  @akbooer
2016-03-30 13:41:22.661   openLuup.luup:0:      version 2016.03.01  @akbooer
2016-03-30 13:41:22.663   openLuup.rooms::     version 2015.10.15  @akbooer
2016-03-30 13:41:22.663   openLuup.requests::  version 2016.03.11  @akbooer
2016-03-30 13:41:22.664   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-30 13:41:22.664   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-30 13:41:22.664   openLuup.init:: loading configuration user_data.json
2016-03-30 13:41:22.664   openLuup.init:: loading user_data json...
2016-03-30 13:41:22.677   openLuup.init:: loading rooms...
2016-03-30 13:41:22.677   openLuup.init:: ...room loading completed
2016-03-30 13:41:22.677   openLuup.init:: loading devices...
2016-03-30 13:41:22.677   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-30 13:41:22.677   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-30 13:41:22.687   luup.create_device:: [3] D_ALTUI.xml / I_ALTUI.xml / D_ALTUI_UI7.json
2016-03-30 13:41:22.689   luup.create_device:: [4] D_openLuupExtensions.xml / I_openLuupExtensions.xml / D_openLuupExtensions.json
2016-03-30 13:41:22.751   luup.create_device:: [6] D_Sonos1.xml / I_Sonos1.xml / D_Sonos1.json
2016-03-30 13:41:22.751   openLuup.init:: loading scenes...
2016-03-30 13:41:22.751   openLuup.init:: number of scenes = 0
2016-03-30 13:41:22.751   openLuup.init:: ...scene loading completed
2016-03-30 13:41:22.751   openLuup.init:: loading installed plugin info...
2016-03-30 13:41:22.751   openLuup.init:: ...user_data loading completed
2016-03-30 13:41:22.751   openLuup.init:: running _openLuup_STARTUP_
2016-03-30 13:41:22.752   openLuup.init:: init phase completed
2016-03-30 13:41:22.752   openLuup.server:: starting HTTP server on 172.16.5.148:3480 tcp{server}: 0xb789a8
2016-03-30 13:41:22.752   openLuup.scheduler:: starting
2016-03-30 13:41:22.752   openLuup.scheduler:: [3] device startup
2016-03-30 13:41:22.752   luup_log:3: ALTUI: initstatus(3) starting version: v1.28
2016-03-30 13:41:22.752   openLuup.scheduler:: [3] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 13:41:22.752   openLuup.scheduler:: [4] device startup
2016-03-30 13:41:22.752   luup.register_handler:4: global_function_name=HTTP_Extensions, request=version
2016-03-30 13:41:22.752   luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine1 was: Uptime 0.04 days now: Uptime 0 #hooks:0
2016-03-30 13:41:22.752   luup.variable_set:4: 4.urn:upnp-org:serviceId:altui1.DisplayLine2 was: Memory 2.1 Mb,  CPU 0 % now:  #hooks:0
2016-03-30 13:41:22.752   openLuup.scheduler:: [4] device startup completed: status=nil, msg=synchronising in 37.2 seconds, name=openLuup:Extensions
2016-03-30 13:41:22.752   openLuup.scheduler:: [6] device startup
2016-03-30 13:41:22.752   luup_log:6: Sonos: #6 starting up with id Sonos
2016-03-30 13:41:22.752   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-30 13:41:22.758   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-30 13:41:22.758   openLuup.scheduler:: [6] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 13:41:22.875   openLuup.server:: new client connection: tcp{client}: 0xb7d888
2016-03-30 13:41:22.876   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=359820630&Timeout=60&MinimumDelay=1500&_=1459361024545 tcp{client}: 0xb7d888
2016-03-30 13:41:23.125   openLuup.server:: new client connection: tcp{client}: 0xb82c48
2016-03-30 13:41:23.126   openLuup.server:: new client connection: tcp{client}: 0xb85958
2016-03-30 13:41:23.126   openLuup.server:: /favicon.ico tcp{client}: 0xb82c48
2016-03-30 13:41:23.126   openLuup.HTTP.FILE:: file not found:favicon.ico
2016-03-30 13:41:23.127   openLuup.server:: request completed (0 bytes, 0 chunks, 0 ms) tcp{client}: 0xb82c48
2016-03-30 13:41:24.129   luup_log:3: ALTUI: startupDeferred, called on behalf of device:3
2016-03-30 13:41:24.129   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.LocalHome was:  now:  #hooks:0
2016-03-30 13:41:24.132   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Version was: v1.28 now: v1.28 #hooks:0

{removed} 

2016-03-30 13:41:24.135   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToSend was:  now:  #hooks:0
2016-03-30 13:41:24.135   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.RemoteVariablesToWatch was:  now:  #hooks:0
2016-03-30 13:41:24.136   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was:  now:  #hooks:0
2016-03-30 13:41:24.136   luup_log:3: ALTUI: Wkflow - enableWorkflows(3,0)
2016-03-30 13:41:24.136   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was:  now:  #hooks:0
2016-03-30 13:41:24.136   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: [] now:  #hooks:0
2016-03-30 13:41:24.136   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was:  now: [] #hooks:0
2016-03-30 13:41:24.136   luup.register_handler:3: global_function_name=myALTUI_Handler, request=ALTUI_Handler
2016-03-30 13:41:24.141   luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunLua 
2016-03-30 13:41:24.142   luup.register_handler:0: global_function_name=ALTUI_LuaRunHandler, request=ALTUI_LuaRunHandler
2016-03-30 13:41:24.142   luup.set_failure:3: status = 0
2016-03-30 13:41:24.142   luup_log:3: ALTUI: startup completed
2016-03-30 13:41:24.142   luup_log:6: Sonos: error: Cannot contact UPnP event proxy: connection refused
2016-03-30 13:41:24.142   luup_log:6: Sonos: UPnP proxy event identified - API version
#6

Interesting. I have just found an old note to myself re. Sonos that says

“accesses iptables (looking for UPnP Proxy?)”

…but not sure what I ever did about that. Will have to dig further.

#7

Yes, looks to be used exclusively for the Discovery Patch (check, install and uninstall)… Will test more tonight and see what happens…

[quote=“akbooer, post:6, topic:191774”]Interesting. I have just found an old note to myself re. Sonos that says

“accesses iptables (looking for UPnP Proxy?)”

…but not sure what I ever did about that. Will have to dig further.[/quote]

#8

rPi3/Debian with the Lua file set to 127.0.0.1 rather than localhost… Things looked good up until 20:24:24.276 (when I pressed the play button). Also, as long as you’re root then the iptables message we often see within the CLI doesn’t show itself anymore.

2016-03-30 20:23:56.376   :: openLuup STARTUP :: 
2016-03-30 20:23:56.377   openLuup.init::      version 2016.02.25  @akbooer
2016-03-30 20:23:56.408   openLuup.scheduler:: version 2016.03.01  @akbooer
2016-03-30 20:23:56.409   openLuup.wsapi::     version 2016.03.05  @akbooer
2016-03-30 20:23:56.409   openLuup.server::    version 2016.03.20  @akbooer
2016-03-30 20:23:56.412   openLuup.plugins::   version 2016.03.05  @akbooer
2016-03-30 20:23:56.416   openLuup.scenes::    version 2016.03.11  @akbooer
2016-03-30 20:23:56.418   openLuup.chdev::     version 2016.02.15  @akbooer
2016-03-30 20:23:56.420   openLuup.io:0:        version 2016.02.15  @akbooer
2016-03-30 20:23:56.420   openLuup.luup:0:      version 2016.03.01  @akbooer
2016-03-30 20:23:56.424   openLuup.rooms::     version 2015.10.15  @akbooer
2016-03-30 20:23:56.424   openLuup.requests::  version 2016.03.11  @akbooer
2016-03-30 20:23:56.424   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-30 20:23:56.424   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-30 20:23:56.425   openLuup.init:: loading configuration user_data.json
2016-03-30 20:23:56.425   openLuup.init:: loading user_data json...
2016-03-30 20:23:56.446   openLuup.init:: loading rooms...
2016-03-30 20:23:56.447   openLuup.init:: ...room loading completed
2016-03-30 20:23:56.447   openLuup.init:: loading devices...
2016-03-30 20:23:56.447   luup.create_device:: [1] D_ZWaveNetwork.xml /  / 
2016-03-30 20:23:56.447   luup.create_device:: [2] D_SceneController1.xml /  / 
2016-03-30 20:23:56.490   luup.create_device:: [3] D_ALTUI.xml / I_ALTUI.xml / D_ALTUI_UI7.json
2016-03-30 20:23:56.795   luup.create_device:: [4] D_Sonos1.xml / I_Sonos1.xml / D_Sonos1.json
2016-03-30 20:23:56.797   openLuup.init:: loading scenes...
2016-03-30 20:23:56.797   openLuup.init:: number of scenes = 0
2016-03-30 20:23:56.797   openLuup.init:: ...scene loading completed
2016-03-30 20:23:56.798   openLuup.init:: loading installed plugin info...
2016-03-30 20:23:56.798   openLuup.init:: ...user_data loading completed
2016-03-30 20:23:56.798   openLuup.init:: running _openLuup_STARTUP_
2016-03-30 20:23:56.798   openLuup.init:: init phase completed
2016-03-30 20:23:56.798   openLuup.server:: starting HTTP server on 10.0.4.138:3480 tcp{server}: 0x16ecae8
2016-03-30 20:23:56.798   openLuup.scheduler:: starting
2016-03-30 20:23:56.798   openLuup.scheduler:: [3] device startup
2016-03-30 20:23:56.798   luup_log:3: ALTUI: initstatus(3) starting version: v1.29
2016-03-30 20:23:56.798   openLuup.scheduler:: [3] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 20:23:56.798   openLuup.scheduler:: [4] device startup
2016-03-30 20:23:56.798   luup_log:4: Sonos: #4 starting up with id Sonos
2016-03-30 20:23:56.798   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:Sonos1.PluginVersion was: 1.4 now: 1.4 #hooks:0
2016-03-30 20:23:56.826   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:Sonos1.DiscoveryPatchInstalled was: 0 now: 0 #hooks:0
2016-03-30 20:23:56.826   openLuup.scheduler:: [4] device startup completed: status=nil, msg=nil, name=nil
2016-03-30 20:23:57.285   openLuup.server:: new client connection: tcp{client}: 0x16f01f8
2016-03-30 20:23:57.286   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=387379379&Timeout=60&MinimumDelay=1500&_=1459387384219 tcp{client}: 0x16f01f8
2016-03-30 20:23:58.287   luup_log:3: ALTUI: startupDeferred, called on behalf of device:3
2016-03-30 20:23:58.287   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.LocalHome was:  now:  #hooks:0
2016-03-30 20:23:58.292   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Version was: v1.29 now: v1.29 #hooks:0

2016-03-30 20:23:58.298   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToSend was:  now:  #hooks:0
2016-03-30 20:23:58.298   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.RemoteVariablesToWatch was:  now:  #hooks:0
2016-03-30 20:23:58.298   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.VariablesToWatch was:  now:  #hooks:0
2016-03-30 20:23:58.299   luup_log:3: ALTUI: Wkflow - enableWorkflows(3,0)
2016-03-30 20:23:58.299   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.Timers was:  now:  #hooks:0
2016-03-30 20:23:58.299   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was: [] now:  #hooks:0
2016-03-30 20:23:58.299   luup.variable_set:3: 3.urn:upnp-org:serviceId:altui1.WorkflowsActiveState was:  now: [] #hooks:0
2016-03-30 20:23:58.299   luup.register_handler:3: global_function_name=myALTUI_Handler, request=ALTUI_Handler
2016-03-30 20:23:58.309   luup.call_action:3: 0.urn:micasaverde-com:serviceId:HomeAutomationGateway1.RunLua 
2016-03-30 20:23:58.310   luup.register_handler:0: global_function_name=ALTUI_LuaRunHandler, request=ALTUI_LuaRunHandler
2016-03-30 20:23:58.311   luup.set_failure:3: status = 0
2016-03-30 20:23:58.311   luup_log:3: ALTUI: startup completed
2016-03-30 20:23:58.311   luup_log:4: Sonos: error: Cannot contact UPnP event proxy: connection refused
2016-03-30 20:23:58.312   luup_log:4: Sonos: UPnP proxy event identified - API version 
2016-03-30 20:23:58.583   luup.variable_set:4: 4.urn:upnp-org:serviceId:ContentDirectory.SavedQueues was: EMPTY now:  #hooks:0
2016-03-30 20:23:58.603   luup.variable_set:4: 4.urn:upnp-org:serviceId:ContentDirectory.FavoritesRadios was: R:0/0/16@AudioCue now: R:0/0/16@AudioCue
R:0/0/11@Speech Server
R:0/0/10@Text-To-Speech
 #hooks:0
2016-03-30 20:23:58.638   luup.variable_set:4: 4.urn:upnp-org:serviceId:ContentDirectory.Favorites was: EMPTY now: FV:2/50@Bethoven's Solveig's Song Radio
FV:2/46@Classical
 #hooks:0
2016-03-30 20:23:58.639   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1459387432 now: 1459387438 #hooks:0
2016-03-30 20:23:59.237   openLuup.server:: request completed (23973 bytes, 2 chunks, 1951 ms) tcp{client}: 0x16f01f8
2016-03-30 20:23:59.243   openLuup.server:: /data_request?id=user_data&output_format=json&DataVersion=387379183&_=1459387384220 tcp{client}: 0x16f01f8
2016-03-30 20:23:59.278   openLuup.server:: request completed (47309 bytes, 3 chunks, 34 ms) tcp{client}: 0x16f01f8
2016-03-30 20:24:01.285   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=387436387&Timeout=60&MinimumDelay=1500&_=1459387384221 tcp{client}: 0x16f01f8
2016-03-30 20:24:05.438   openLuup.server:: new client connection: tcp{client}: 0x1755888
2016-03-30 20:24:05.438   openLuup.server:: /luvd/J_Sonos1.js tcp{client}: 0x1755888
2016-03-30 20:24:05.448   openLuup.server:: request completed (61411 bytes, 4 chunks, 9 ms) tcp{client}: 0x1755888
2016-03-30 20:24:06.949   openLuup.server:: /cgi-bin/cmh/sysinfo.sh tcp{client}: 0x1755888
2016-03-30 20:24:06.951   openLuup.wsapi:: file not found: /cgi-bin/cmh/sysinfo.sh
2016-03-30 20:24:06.953   openLuup.server:: request completed (39 bytes, 1 chunks, 4 ms) tcp{client}: 0x1755888
2016-03-30 20:24:08.246   openLuup.server:: /cgi-bin/cmh/sysinfo.sh tcp{client}: 0x1755888
2016-03-30 20:24:08.247   openLuup.server:: request completed (0 bytes, 0 chunks, 1 ms) tcp{client}: 0x1755888
2016-03-30 20:24:09.604   openLuup.server:: /cgi-bin/cmh/sysinfo.sh tcp{client}: 0x1755888
2016-03-30 20:24:09.605   openLuup.server:: request completed (0 bytes, 0 chunks, 0 ms) tcp{client}: 0x1755888
2016-03-30 20:24:14.441   openLuup.server:: /cgi-bin/cmh/sysinfo.sh tcp{client}: 0x1755888
2016-03-30 20:24:14.442   openLuup.server:: request completed (0 bytes, 0 chunks, 1 ms) tcp{client}: 0x1755888
2016-03-30 20:24:17.949   openLuup.server:: /data_request/data_request?id=lu_action&output_format=xml&DeviceNum=4&serviceId=urn%3Amicasaverde-com%3AserviceId%3AVolume1&action=Down tcp{client}: 0x1755888
2016-03-30 20:24:17.950   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Volume1.Down 
2016-03-30 20:24:17.971   luup.variable_set:4: 4.urn:upnp-org:serviceId:RenderingControl.Volume was: 16 now: 13 #hooks:0
2016-03-30 20:24:17.972   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1459387438 now: 1459387457 #hooks:0
2016-03-30 20:24:17.974   openLuup.server:: request completed (103 bytes, 1 chunks, 25 ms) tcp{client}: 0x1755888
2016-03-30 20:24:18.490   openLuup.server:: request completed (13141 bytes, 1 chunks, 17204 ms) tcp{client}: 0x16f01f8
2016-03-30 20:24:18.595   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=387436389&Timeout=60&MinimumDelay=1500&_=1459387384222 tcp{client}: 0x16f01f8
2016-03-30 20:24:18.732   openLuup.server:: /data_request/data_request?id=lu_action&output_format=xml&DeviceNum=4&serviceId=urn%3Amicasaverde-com%3AserviceId%3AVolume1&action=Down tcp{client}: 0x1755888
2016-03-30 20:24:18.733   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Volume1.Down 
2016-03-30 20:24:18.748   luup.variable_set:4: 4.urn:upnp-org:serviceId:RenderingControl.Volume was: 13 now: 10 #hooks:0
2016-03-30 20:24:18.748   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1459387457 now: 1459387458 #hooks:0
2016-03-30 20:24:18.750   openLuup.server:: request completed (103 bytes, 1 chunks, 17 ms) tcp{client}: 0x1755888
2016-03-30 20:24:19.374   openLuup.server:: /data_request/data_request?id=lu_action&output_format=xml&DeviceNum=4&serviceId=urn%3Amicasaverde-com%3AserviceId%3AVolume1&action=Up tcp{client}: 0x1755888
2016-03-30 20:24:19.375   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Volume1.Up 
2016-03-30 20:24:19.390   luup.variable_set:4: 4.urn:upnp-org:serviceId:RenderingControl.Volume was: 10 now: 13 #hooks:0
2016-03-30 20:24:19.390   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1459387458 now: 1459387459 #hooks:0
2016-03-30 20:24:19.392   openLuup.server:: request completed (99 bytes, 1 chunks, 18 ms) tcp{client}: 0x1755888
2016-03-30 20:24:20.410   openLuup.server:: request completed (13019 bytes, 1 chunks, 1814 ms) tcp{client}: 0x16f01f8
2016-03-30 20:24:20.515   openLuup.server:: /data_request?id=lu_status2&output_format=json&DataVersion=387436393&Timeout=60&MinimumDelay=1500&_=1459387384223 tcp{client}: 0x16f01f8
2016-03-30 20:24:24.267   openLuup.server:: /data_request/data_request?id=lu_action&output_format=xml&DeviceNum=4&serviceId=urn%3Amicasaverde-com%3AserviceId%3ASonos1&action=PlayURI&URIToPlay=ID%253AFV%253A2%252F50 tcp{client}: 0x1755888
2016-03-30 20:24:24.268   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Sonos1.PlayURI 


2016-03-30 20:24:24.276   luup_log:4: Sonos: error: UPnP_request (SetAVTransportURI, urn:schemas-upnp-org:service:AVTransport:1): status=1 statusMsg=500 result=[<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>714</errorCode></UPnPError></detail></s:Fault></s:Body></s:Envelope>]
2016-03-30 20:24:24.382   luup_log:4: Sonos: error: UPnP_request (Play, urn:schemas-upnp-org:service:AVTransport:1): status=1 statusMsg=500 result=[<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>701</errorCode></UPnPError></detail></s:Fault></s:Body></s:Envelope>]
2016-03-30 20:24:24.485   openLuup.server:: request completed (109 bytes, 1 chunks, 218 ms) tcp{client}: 0x1755888
tcp{client}: 0x1755888

AND the oddest thing ever, if I start the music using the Sonos app on my iPad - I then have what appears to be control over the Sonos device(s)…

Device:
[1] Start
[2] Stop

Control:
[1] Track info
[2] Play, pause, stop, vol, mute and next operate.

Player:
[1] Play
[2] Stop
[3] Album art is displayed

Help:
[1] Works, I can only assume it needed track info in order to render…

I’ve since added 2 more Sonos systems and they wouldn’t work until I started a track from the Sonos app. I’m confused about all of this… Posting logs of the startup and operation of all 3 devices. I’m going to sleep on this one and see if it all still operates in the morning.

#9

And I’ve slept and all 3 of them are still working even after a reboot… So I’ll move the remainder over tonight to this test box and do some further testing using TTS.
So questions remain.

[1] Why does the code have to be adjusted from localhost to 127.0.0… Am I missing something in a Linux config perhaps ?
[2] When adding a device it seems it won’t work out-of-the box until an external device (e.g Sonos for iPad, Android, Windows) initiates a stream. Then it’s happy.

#10

Could be. Whatever it is, it’s not an openLuup fix, since it’s just a call to http.request()

[2] When adding a device it seems it won't work out-of-the box until an external device (e.g Sonos for iPad, Android, Windows) initiates a stream. Then it's happy.

Don’t know either, but if it’s just a one-off fix then I could live with that. I may have had the same issue once, but I did so many things to begin with, trying to get TTS to work (seems it was a Google problem) it’s lost in the mists of time.

#11

I checked the hosts file and everything looks good so I’m not sure what to change if anything. And yes, I can live with this if it works and it just one step closer to having most everything non-zwave running successfully on openLuup. I’ll keep this thread going with updates on TTS and see if I can find the root cause of the localhost issue.

Could be. Whatever it is, it’s not an openLuup fix, since it’s just a call to http.request()

[2] When adding a device it seems it won't work out-of-the box until an external device (e.g Sonos for iPad, Android, Windows) initiates a stream. Then it's happy.

Don’t know either, but if it’s just a one-off fix then I could live with that. I may have had the same issue once, but I did so many things to begin with, trying to get TTS to work (seems it was a Google problem) it’s lost in the mists of time.[/quote]

#12

Update:

Looks like TTS will require a /www directory. A symbolic resolved my error (SonosTTS line 147) but I can’t tell (@ work) if the speech is being delivered. Should also note that an action will certainly kick-off a favorite however selecting a favorite via the UI will not (another UPnP error in the log).

Edit: wget needs adjustment (location of arguments) within the TTS file. Will post once I figure out this encoding issue (ugh).
Edit: Sonos Implementation file; need to adjust the VERA_WEB_PORT from 80 to 3480…

local SAY_TMP_FILE = "/tmp/Say.%s.%s.mp3"
local SAY_OUTPUT_FILE = "/www/Say.%s.%s"
local SAY_OUTPUT_URI = "%s/Say.%s.%s"
local CONCAT_EXECUTE = "cat %s > %s ; rm %s"
local DELETE_EXECUTE = "rm /www/Say.%s.*"
#13

Re-ran my test this morning and spotted something odd [openLuup.server:: Unsupported HTTP request:HEAD], I’m not sure what’s occurring here but obviously something to do with this plugin pushing the MP3 file through requesting Sonos to access the file via openLuup…

When I played the mp3 file using Sonos it works, no complaint regarding the encoding issue. When I execute an action for say within openLuup, the Sonos app tells me it’s not properly encoded. I’m not sure how much further I can go with troubleshooting … Hoping for any pointers here …

2016-04-01 08:38:14.468   luup_log:0: ALTUI: runLua(luup.call_action("urn:micasaverde-com:serviceId:Sonos1", "Say",{Text="Here comes the sun.", Volume=30},6))
2016-04-01 08:38:14.469   luup.call_action:0: 6.urn:micasaverde-com:serviceId:Sonos1.Say 
2016-04-01 08:38:14.469   luup_log:6: ((CUDA))-----------------------------------------------------
2016-04-01 08:38:14.469   luup_log:6: [TTS Debug]: OSXserverURL= [http://10.0.3.11:8080]
2016-04-01 08:38:14.469   luup_log:6: [TTS Debug]: file = [/www/Say.6.mp3]
2016-04-01 08:38:14.469   luup_log:6: [TTS Debug]: Constructed returnCocde= [rm -f /www/Say.6.mp3 ; wget --output-document /www/Say.6.mp3 \
--header "Accept-Charset: utf-8;q=0.7,*;q=0.3" \
--header "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8" \
--user-agent "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.64 Safari/537.11" \
"http://10.0.3.11:8080/tts?text=Here%20comes%20the%20sun%2e -O /www/Say.6.mp3"]
2016-04-01 08:38:14.708   luup_log:6: [TTS Debug]: POST returnCocde= [0]
2016-04-01 08:38:14.708   luup_log:6: [TTS Debug]: duration = [8]
2016-04-01 08:38:14.709   luup_log:6: [TTS Debug]: localBaseURL = [http://10.0.4.138:3480]
2016-04-01 08:38:14.709   luup_log:6: [TTS Debug]: device = [6]
2016-04-01 08:38:14.709   luup_log:6: [TTS Debug]: PRE returnCocde= [0]
2016-04-01 08:38:14.710   luup_log:6: [TTS Debug]: uri = [http://10.0.4.138:3480/Say.6.mp3]
2016-04-01 08:38:14.710   luup_log:6: ((CUDA))-----------------------------------------------------
2016-04-01 08:38:20.052   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.TransportState was: STOPPED now: TRANSITIONING #hooks:0
2016-04-01 08:38:20.096   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.AVTransportURI was: x-rincon-queue:RINCON_B8E937B105E001400#0 now: http://10.0.4.138:3480/Say.6.mp3 #hooks:0
2016-04-01 08:38:20.107   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.CurrentTrackDuration was: 0:00:07 now: 0:00:00 #hooks:0
2016-04-01 08:38:20.108   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.CurrentTrackURI was: x-file-cifs://10.0.3.10/Audio/Say.5.mp3 now: http://10.0.4.138:3480/Say.6.mp3 #hooks:0
2016-04-01 08:38:20.108   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.CurrentTrackMetaData was: <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="-1" parentID="-1" restricted="true"><res protocolInfo="x-file-cifs:*:audio/mpeg:*" duration="0:00:07">x-file-cifs://10.0.3.10/Audio/Say.5.mp3</res><r:streamContent></r:streamContent><dc:title>Say.5.mp3</dc:title><upnp:class>object.item.audioItem.musicTrack</upnp:class></item></DIDL-Lite> now: <DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/"><item id="-1" parentID="-1" restricted="true"><res protocolInfo="http-get:*:application/octet-stream:*">http://10.0.4.138:3480/Say.6.mp3</res><r:streamContent></r:streamContent><dc:title>Say.6.mp3</dc:title><upnp:class>object.item</upnp:class></item></DIDL-Lite> #hooks:0
2016-04-01 08:38:20.109   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.CurrentStatus was: Say.5.mp3 now: Say.6.mp3 #hooks:0
2016-04-01 08:38:20.109   luup.variable_set:6: 6.urn:upnp-org:serviceId:AVTransport.CurrentTitle was: Say.5.mp3 now: Say.6.mp3 #hooks:0
2016-04-01 08:38:20.123   luup.variable_set:6: 6.urn:upnp-org:serviceId:RenderingControl.Volume was: 9 now: 30 #hooks:0
2016-04-01 08:38:20.123   luup.variable_set:6: 6.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1459517882 now: 1459517900 #hooks:0
2016-04-01 08:38:20.123   luup_log:0: ALTUI: Evaluation of lua code returned: nil
2016-04-01 08:38:20.125   openLuup.server:: request completed (8 bytes, 1 chunks, 5657 ms) tcp{client}: 0x1100778
2016-04-01 08:38:20.238   luup_log:5: Sonos: debug: refreshNow: device=5
2016-04-01 08:38:20.461   openLuup.server:: new client connection: tcp{client}: 0x1109b00
2016-04-01 08:38:20.461   openLuup.server:: new client connection: tcp{client}: 0x110bb78
2016-04-01 08:38:20.478   openLuup.server:: request completed (15813 bytes, 1 chunks, 15566 ms) tcp{client}: 0x109f438
2016-04-01 08:38:20.479   openLuup.server:: /Say.6.mp3 tcp{client}: 0x1109b00
2016-04-01 08:38:20.479   openLuup.server:: /Say.6.mp3 tcp{client}: 0x110bb78
2016-04-01 08:38:20.480   openLuup.HTTP.FILE:: file not found:Say.6.mp3
2016-04-01 08:38:20.480   openLuup.server:: request completed (0 bytes, 0 chunks, 1 ms) tcp{client}: 0x1109b00
2016-04-01 08:38:20.480   openLuup.HTTP.FILE:: file not found:Say.6.mp3
2016-04-01 08:38:20.481   openLuup.server:: request completed (0 bytes, 0 chunks, 1 ms) tcp{client}: 0x110bb78
2016-04-01 08:38:20.481   openLuup.server:: receive error: closed tcp{client}: 0x1109b00
2016-04-01 08:38:20.485   openLuup.server:: new client connection: tcp{client}: 0x10b7ea0
2016-04-01 08:38:20.485   openLuup.server:: /Say.6.mp3 tcp{client}: 0x10b7ea0
2016-04-01 08:38:20.485   openLuup.server:: Unsupported HTTP request:HEAD
2016-04-01 08:38:20.486   openLuup.HTTP.FILE:: file not found:Say.6.mp3
#14

Interesting. Although I ran across the “file not found” problem when trying TTS, it seemed to be linked to the patchy availability of Google Translate. It didn’t seem to be a problem when using Microsoft, although I gather that has its own issues from time to time.

The HEAD request error is understandable: the openLuup server does, indeed, not support it - mostly though my laziness and the fact that I’ve never seen anything else require that. Should be not to hard to add it.

#15

Depending on the distro, IF we don’t have a /www then yes - it’ll throw an error (not really an error though). We could point this somewhere else (somewhere within openLuup) to keep it happy. Otherwise if /www exists then it’s programmed to remove the file in the event one already exists (a fail-safe of sorts). So I added -f to the rm command and that quiets that down (-f; ignore nonexistent files, never prompt). So with a slight modification of the wget arg’s everything runs pretty smoothly. I see other speech functions doing the same (wget) so those would need to be modified as well. You’re right though, Microsoft does work as I accidentally tripped on it the other day. I’ll do my best to clean up what I can or at the very least add more debugging to the file so the other TTS methods work… Hate having to change all this to be honest.

So it sound as if the Sonos is fetching the file off Vera… Makes sense, had to lookup the HEAD method ! For those wondering, an excerpt is below…

The HEAD method is identical to GET except that the server MUST NOT return a message-body in the response. The meta information contained in the HTTP headers in response to a HEAD request SHOULD be identical to the information sent in response to a GET request. This method can be used for obtaining meta information about the entity implied by the request without transferring the entity-body itself. This method is often used for testing hypertext links for validity, accessibility, and recent modification.

Interesting. Although I ran across the “file not found” problem when trying TTS, it seemed to be linked to the patchy availability of Google Translate. It didn’t seem to be a problem when using Microsoft, although I gather that has its own issues from time to time.

The HEAD request error is understandable: the openLuup server does, indeed, not support it - mostly though my laziness and the fact that I’ve never seen anything else require that. Should be not to hard to add it.[/quote]

#16

So what’s the change needed to the wgets? The openLuup server already has some special cases it catches, like icons, references to /luvd/ (which does not exist), cgi, etc…

I can make a change if it’s robust and generally required.

Re. the “rm” command, this is poor programming in the plugin, I’m afraid. Lua has a perfectly good, system independent, os.remove() function which does not complain if the file is absent. In general, os.execute is a very, very bad idea.

#17

Yes, os.execute is used moderately throughout…

Vera version:

        local SAY_EXECUTE = "rm %s ; wget --output-document %s" .. [[ \
--quiet \
--header "Accept-Charset: utf-8;q=0.7,*;q=0.3" \
--header "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8" \
--user-agent "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.64 Safari/537.11" \
"%s/tts?text=%s"]]

local returnCocde = os.execute(SAY_EXECUTE:format(file, file, OSXserverURL, url.escape(text)))

Modified version:

        local SAY_EXECUTE = "rm -f %s ; wget -O %s " .. [[ \
--header "Accept-Charset: utf-8;q=0.7,*;q=0.3" \
--header "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8" \
--user-agent "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_2) AppleWebKit/537.11 (KHTML, like Gecko) Chrome/23.0.1271.64 Safari/537.11" \
"%s/tts?text=%s"]]

local returnCocde = os.execute(SAY_EXECUTE:format(file, file, OSXserverURL, url.escape(text), file))

CLI result of modified code.

--2016-04-01 20:57:55--  http://10.0.3.11:8080/tts?text=Here%20comes%20the%20sun%2e
Connecting to 10.0.3.11:8080... connected.
HTTP request sent, awaiting response... 200 OK
Length: 11381 (11K) [audio/mpeg]
Saving to: '/www/Say.5.mp3'

/www/Say.5.mp3                 100%[===================================================>]  11.11K  --.-KB/s   in 0s

2016-04-01 20:57:56 (31.9 MB/s) - ?/www/Say.5.mp3? saved [11381/11381]

[quote=“akbooer, post:16, topic:191774”]So what’s the change needed to the wgets? The openLuup server already has some special cases it catches, like icons, references to /luvd/ (which does not exist), cgi, etc…

I can make a change if it’s robust and generally required.

Re. the “rm” command, this is poor programming in the plugin, I’m afraid. Lua has a perfectly good, system independent, os.remove() function which does not complain if the file is absent. In general, os.execute is a very, very bad idea.[/quote]

#18

Ah, OK, I thought you meant luup.inet.wget().

#19

That was my bad, I should have clarified… Still looking into this HEAD method in relation to Sonos… Not a whole lot out there … Hopefully this is the final hurdle…

#20

Might want to hold off on implementing the HEAD method… I thought of a workaround tonight for the OSXTTS that could keep this all Lua (that is if I can code it)…