openLuup: AV plugins

Plugins & Plugin Development openLuup
21

AND the leveling begins…

22

You do have /usr/bin/GetNetworkState.sh? That’s the major external dependency I know. If you DO have it, did you force a fixed IP? It won’t then work on a different machine.

23

Yes, that was one of the first things I checked & re-checked. All my IP’s are dhcp’d with reservations set at the firewall. So all should ‘have’ been good. I’ll know soon if this resolved the issue…

You do have /usr/bin/GetNetworkState.sh? That’s the major external dependency I know. If you DO have it, did you force a fixed IP? It won’t then work on a different machine.[/quote]

24

Apparently it has everything to do with Ubuntu Server, totally fresh install and the exact same symptoms. Ubuntu Mate has no issues other than the TTS (just so others know). On to plan B, move them back to Vera and use them in bridge mode.

25

So what’s wrong with using RPi?

26

Actually nothing, however I’ve quite enjoyed taking it with me to work for testing. Since the cost of these are so low, I could always get another one…
Having a hard time getting past this thing not working on the server, can’t imagine what’s happening.

27

@akbooer

OK, Chaos Calmer has Sonos working quite nicely… In testing the TTS again tonight I found it interesting…

rm: can't remove '/www/Say.7.mp3': No such file or directory
wget: server returned error: HTTP/1.1 403 Forbidden

And then I checked the URL and changed it from [http://10.0.3.11:8080/] to this [http://10.0.3.11:8080]…
And then there was perfect speech…

Can you confirm on your end if this corrects anything. I do still see the message though…

rm: can't remove '/www/Say.7.mp3': No such file or directory
28

Hmm,

Well seems that was short lived… Will try to get more detailed logs tomorrow, need sleep. Google Chrome console shows errors when opening a Sonos device and openLuup extensions. Seems if I mess with the Sonos TTS enough, I can make it work for a short period of time. So it seems there’s hope if we can isolate the ‘why’.

2015-11-10 23:51:07.745   openLuup.server:: /data_request?id=lu_action&output_format=xml&DeviceNum=7&serviceId=urn:micasaverde-com:serviceId:Sonos1&action=Say&Text=Hey%20You&Language=en&Engine=OSX_TTS_SERVER&Volume=22&GroupZones=&SameVolumeForAll=false tcp{client}: 0x1951878
2015-11-10 23:51:07.746   luup.call_action:: 7.urn:micasaverde-com:serviceId:Sonos1.Say 
2015-11-10 23:51:07.907   openLuup.context_switch::  ERROR: [string "device_10"]:1413: bad argument #1 to 'find' (string expected, got nil)

[quote=“CudaNet, post:27, topic:189395”]@akbooer

OK, Chaos Calmer has Sonos working quite nicely… In testing the TTS again tonight I found it interesting…

rm: can't remove '/www/Say.7.mp3': No such file or directory
wget: server returned error: HTTP/1.1 403 Forbidden

And then I checked the URL and changed it from [http://10.0.3.11:8080/] to this [http://10.0.3.11:8080]…
And then there was perfect speech…

Can you confirm on your end if this corrects anything. I do still see the message though…

rm: can't remove '/www/Say.7.mp3': No such file or directory [/quote]

29

Very hard to debug with a full system And so little information. What is device #10 in this case? It looks like the Sonos is #7?

30

[quote=“CudaNet, post:27, topic:189395”]And then I checked the URL and changed it from [http://10.0.3.11:8080/] to this [http://10.0.3.11:8080]…
And then there was perfect speech…

Can you confirm on your end if this corrects anything. I do still see the message though…[/quote]

Which URL would that be?

31

Yes, device 10 is indeed a Sonos (Amp). For this test, all I have installed (well, with exception of openLuup ext.) are 5 Sonos devices. Odd that device 10 is complaining when I’m not even sending an action to it.
Sorry for being vague at that late of an hour, should have just called it quits and revisited it when I’m thinking clearly.

32

Disregard my craziness… The URL I was referring too in my sleep deprivation was the speech server URL.
I’ve pruned the config down to a single Sonos device, all is working - meaning TTS and music. Reloaded and it holds up until I halt the engine/reboot the server.

I had the Sonos debug logs on and they are thick ! It’s trying to speak, even pauses the music temporarily…
Will post them when I get to work…

[quote=“akbooer, post:30, topic:189395”][quote=“CudaNet, post:27, topic:189395”]And then I checked the URL and changed it from [http://10.0.3.11:8080/] to this [http://10.0.3.11:8080]…
And then there was perfect speech…

Can you confirm on your end if this corrects anything. I do still see the message though…[/quote]

Which URL would that be?[/quote]

33

I’m not sure what the sequence of events was when you generated all this, but I do see this:

2015-11-11 08:36:54.142   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=&_=1447252519655 tcp{client}: 0x233e4a8
2015-11-11 08:36:54.142   luup_log:3: ALTUI: ALTUI_Handler: request is: lr_ALTUI_Handler
2015-11-11 08:36:54.142   luup_log:3: ALTUI: ALTUI_Handler: parameters is: {"command":"oscommand","_":"1447252519655"}
2015-11-11 08:36:54.143   luup_log:3: ALTUI: ALTUI_Handler: outputformat is: null
2015-11-11 08:36:54.143   openLuup.context_switch::  ERROR: [string "device_3"]:106: bad argument #1 to 'gsub' (string expected, got nil)
2015-11-11 08:36:54.143   openLuup.server:: error in callback: lr_ALTUI_Handler, error is [string "device_3"]:106: bad argument #1 to 'gsub' (string expected, got nil)

…which looks like you tried to execute an empty Lua Test window in AltUI.

So there’s obviously more than Sonos stuff happening in this time interval.

34

I don’t recall executing an empty Lua window…
I was looking at the log data and I noticed this occurred many times within failed ‘[i]http://0.0.0.0:80/Say.4.mp3[/i]’. Although I never see it in the success log.

Does this seem right to you ? Their all over the failed log…

-- Failed Log
2015-11-11 08:36:03.073   luup_log:4: Sonos: debug: UPnP_request: status=1 statusMsg=200 result=[<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetVolumeResponse xmlns:u="urn:schemas-upnp-org:service:RenderingControl:1"><CurrentVolume>32</CurrentVolume></u:GetVolumeResponse></s:Body></s:Envelope>]
2015-11-11 08:36:03.073   luup.variable_set:4: 4.urn:micasaverde-com:serviceId:HaDevice1.LastUpdate was: 1447252552 now: 1447252563 #hooks:0
2015-11-11 08:36:03.074   luup_log:4: Sonos: debug: uri: http://0.0.0.0:80/Say.4.mp3
2015-11-11 08:36:03.074   luup_log:4: Sonos: debug: uriMetaData: 
2015-11-11 08:36:03.074   luup_log:4: Sonos: debug: service.__index: Accessing non-existing function SetAVTransportURI
2015-11-11 08:36:03.074   luup_log:4: Sonos: debug: SetAVTransportURI('http://10.0.4.20:1400/MediaRenderer/AVTransport/Control', 'urn:schemas-upnp-org:service:AVTransport:1') Called with parameter count=1
2015-11-11 08:36:03.074   luup_log:4: Sonos: debug: UPnP_request: url=[http://10.0.4.20:1400/MediaRenderer/AVTransport/Control], body=[<?xml version="1.0" encoding="utf-8"?>

[quote=“akbooer, post:33, topic:189395”]I’m not sure what the sequence of events was when you generated all this, but I do see this:

2015-11-11 08:36:54.142   openLuup.server:: /data_request?id=lr_ALTUI_Handler&command=oscommand&oscommand=&_=1447252519655 tcp{client}: 0x233e4a8
2015-11-11 08:36:54.142   luup_log:3: ALTUI: ALTUI_Handler: request is: lr_ALTUI_Handler
2015-11-11 08:36:54.142   luup_log:3: ALTUI: ALTUI_Handler: parameters is: {"command":"oscommand","_":"1447252519655"}
2015-11-11 08:36:54.143   luup_log:3: ALTUI: ALTUI_Handler: outputformat is: null
2015-11-11 08:36:54.143   openLuup.context_switch::  ERROR: [string "device_3"]:106: bad argument #1 to 'gsub' (string expected, got nil)
2015-11-11 08:36:54.143   openLuup.server:: error in callback: lr_ALTUI_Handler, error is [string "device_3"]:106: bad argument #1 to 'gsub' (string expected, got nil)

…which looks like you tried to execute an empty Lua Test window in AltUI.

So there’s obviously more than Sonos stuff happening in this time interval.[/quote]

35

Well this looks like the machine has not picked up the right IP address. Have you verified that good old [tt]/usr/bin/GetNetworkState.sh[/tt] is actually working?

36

Absolutely, I’ve even made it a point in all the documentation and a test to verify that it works.

	> Execute it from the [/usr/bin] directory
	$./GetNetworkState.sh
	{yourIPhere}{user}@server:/usr/bin$

Well this looks like the machine has not picked up the right IP address. Have you verified that good old [tt]/usr/bin/GetNetworkState.sh[/tt] is actually working?[/quote]

37

I think I’ve isolated the problem, I’ll try this for a day and see how well it holds. I wrote a quick scene that logs the IP address using GetNetworkState and writing it to the openLuup log.
I test TTS and it worked just fine. I then rebooted the physical server and tested again. Sure enough no TTS. In looking at the logs, openLuup started with 0.0.0.0. I then cross referenced that data with the log data written by OpenWRT. Sure enough, the system boots so fast that openLuup/Sonos plugin never got a chance to get an IP address. The difference was around 6 seconds between openLuup starting and OpenWRT getting a lease from the DHCP server. So I simply added a 10 second delay to the shell script.

Re-tested and it’s working…

OpenWRT: Wed Nov 11 19:15:31 2015 daemon.notice netifd: lan (1335): Lease of 10.0.4.10 obtained, lease time 7200

Wed Nov 11 19:15:25 2015 auth.info sshd[1250]: Server listening on :: port 22.
Wed Nov 11 19:15:25 2015 auth.info sshd[1250]: Server listening on 0.0.0.0 port 22.
Wed Nov 11 19:15:25 2015 kern.info kernel: [   10.471577] 8021q: adding VLAN 0 to HW filter on device eth0
Wed Nov 11 19:15:25 2015 kern.info kernel: [   10.477828] device eth0 entered promiscuous mode
Wed Nov 11 19:15:25 2015 daemon.notice netifd: Interface 'lan' is enabled
Wed Nov 11 19:15:25 2015 daemon.notice netifd: Interface 'loopback' is enabled
Wed Nov 11 19:15:25 2015 daemon.notice netifd: Interface 'loopback' is setting up now
Wed Nov 11 19:15:25 2015 daemon.notice netifd: Interface 'loopback' is now up
Wed Nov 11 19:15:25 2015 kern.info kernel: [   10.483345] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
Wed Nov 11 19:15:25 2015 daemon.notice netifd: Network device 'lo' link is up
Wed Nov 11 19:15:25 2015 daemon.notice netifd: Interface 'loopback' has link connectivity 
Wed Nov 11 19:15:27 2015 kern.info kernel: [   13.014663] e1000e: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: None
Wed Nov 11 19:15:27 2015 kern.info kernel: [   13.022647] br-lan: port 1(eth0) entered forwarding state
Wed Nov 11 19:15:27 2015 kern.info kernel: [   13.028186] br-lan: port 1(eth0) entered forwarding state
Wed Nov 11 19:15:27 2015 daemon.notice netifd: Network device 'eth0' link is up
Wed Nov 11 19:15:27 2015 daemon.notice netifd: Bridge 'br-lan' link is up
Wed Nov 11 19:15:27 2015 daemon.notice netifd: Interface 'lan' has link connectivity 
Wed Nov 11 19:15:27 2015 daemon.notice netifd: Interface 'lan' is setting up now
Wed Nov 11 19:15:27 2015 kern.info kernel: [   13.033865] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Wed Nov 11 19:15:27 2015 daemon.notice netifd: lan (1335): udhcpc (v1.23.2) started
Wed Nov 11 19:15:27 2015 daemon.notice netifd: lan (1335): Sending discover...
Wed Nov 11 19:15:29 2015 kern.info kernel: [   15.025063] br-lan: port 1(eth0) entered forwarding state
Wed Nov 11 19:15:30 2015 daemon.notice netifd: lan (1335): Sending discover...
Wed Nov 11 19:15:31 2015 daemon.notice netifd: lan (1335): Sending select for 10.0.4.10...
Wed Nov 11 19:15:31 2015 daemon.notice netifd: lan (1335): Lease of 10.0.4.10 obtained, lease time 7200
Wed Nov 11 19:15:31 2015 daemon.notice netifd: Interface 'lan' is now up

openLuup: 2015-11-11 19:15:25.530 openLuup.server:: starting HTTP server on 0.0.0.0:3480 tcp{server}: 0x231b9d8

2015-11-11 19:15:25.328   :: openLuup STARTUP :: 
2015-11-11 19:15:25.328   openLuup.init::      version 2015.11.01  @akbooer
2015-11-11 19:15:25.343   openLuup.scheduler:: version 2015.11.03  @akbooer
2015-11-11 19:15:25.343   openLuup.server::    version 2015.11.01  @akbooer
2015-11-11 19:15:25.346   openLuup.plugins::   version 2015.11.06  @akbooer
2015-11-11 19:15:25.349   openLuup.scenes::    version 2015.10.26  @akbooer
2015-11-11 19:15:25.350   openLuup.chdev::     version 2015.11.01  @akbooer
2015-11-11 19:15:25.351   openLuup.io::        version 2015.10.15  @akbooer
2015-11-11 19:15:25.352   openLuup.luup::      version 2015.11.03  @akbooer
2015-11-11 19:15:25.356   openLuup.rooms::     version 2015.10.15  @akbooer
2015-11-11 19:15:25.356   openLuup.requests::  version 2015.10.30  @akbooer
2015-11-11 19:15:25.356   luup.create_device:: [1] urn:schemas-micasaverde-com:device:ZWaveNetwork:1 / no-implementation-file
2015-11-11 19:15:25.356   luup.create_device:: [2] urn:schemas-micasaverde-com:device:SceneController:1 / no-implementation-file
2015-11-11 19:15:25.357   openLuup.init:: loading configuration user_data.json
2015-11-11 19:15:25.357   openLuup.init:: loading user_data json...
2015-11-11 19:15:25.376   openLuup.init:: loading rooms...
2015-11-11 19:15:25.376   openLuup.init:: room#1 'Upstairs'
2015-11-11 19:15:25.377   openLuup.init:: room#2 'Downstairs'
2015-11-11 19:15:25.377   openLuup.init:: ...room loading completed
2015-11-11 19:15:25.377   openLuup.init:: loading devices...
2015-11-11 19:15:25.377   openLuup.init:: [1] 'ZWave', urn:schemas-micasaverde-com:device:ZWaveNetwork:1
2015-11-11 19:15:25.377   openLuup.init:: [2] '_SceneController', urn:schemas-micasaverde-com:device:SceneController:1
2015-11-11 19:15:25.377   openLuup.init:: [3] 'ALTUI', urn:schemas-upnp-org:device:altui:1
2015-11-11 19:15:25.403   openLuup.init:: [4] 'Sonos', urn:schemas-micasaverde-com:device:Sonos:1
2015-11-11 19:15:25.528   openLuup.init:: loading scenes...
2015-11-11 19:15:25.528   openLuup.init:: number of scenes = 1
2015-11-11 19:15:25.529   openLuup.init:: scene#1 'My IP Address'
2015-11-11 19:15:25.529   openLuup.init:: ...scene loading completed
2015-11-11 19:15:25.529   openLuup.init:: loading installed plugin info...
2015-11-11 19:15:25.529   openLuup.init:: ...user_data loading completed
2015-11-11 19:15:25.529   openLuup.init:: running _openLuup_STARTUP_
2015-11-11 19:15:25.529   openLuup.init:: startup completed
2015-11-11 19:15:25.530   openLuup.server:: starting HTTP server on 0.0.0.0:3480 tcp{server}: 0x231b9d8
2015-11-11 19:15:25.530   openLuup.scheduler:: starting
2015-11-11 19:15:25.530   openLuup.scheduler:3: device startup
2015-11-11 19:15:25.530   luup_log:3: ALTUI: initstatus(3) starting version: v0.96
2015-11-11 19:15:25.530   openLuup.scheduler:3: device startup completed: status=nil, msg=nil, name=nil
2015-11-11 19:15:25.531   openLuup.scheduler:4: device startup
38

That would seem to explain it. I could build in a check right at the start of the openLuup init phase to see if the IP is valid, but maybe this is more of a system configuration issue? Something for documentation, anyway!

39

Yes, once I observed both Sonos and openLuup with their IP’s set to zero’s, I kind of knew. Checked it this morning and it’s held. I’ll add it to the install guide.

40

Unfortunately the problem isn’t resolved. One speaker works perfect, TTS, music etc… I added a 2nd to see if things were still good. The answer was no.
Sequence of events:

[1] Start clean with 1 Sonos (device 4).
[2] Use Lua test to make device 4 speak. Works
[3] Run Lua to add another Sonos device. Device 5 was added.

luup.create_device ('', "IOS Push", "IOS Push", "D_IosPush.xml")

[4] Configured device 5, discovered IP - worked, configured TTS, set for OSX.
[5] Went to devices and I can see 2 Sonos systems. Started music on device [4] - worked. Stopped. Started music on device [5] - worked. Stopped.
[6] Using same Lua test as step [2], I ran it again. No speech.

2015-11-13 01:05:03.477   openLuup.context_switch:0:  ERROR: [string "device_5"]:1413: bad argument #1 to 'find' (string expected, got nil)

[7] Remove device [5].
[8] Use Lua test to make device 4 speak. Works.

Device [4] running TTS:

2015-11-13 01:01:36.790   openLuup.server:: /data_request?id=lr_ALTUI_LuaRunHandler&command=run_lua&lua=luup.call_action(%22urn%3Amicasaverde-com%3AserviceId%3ASonos1%22%2C%20%22Say%22%2C%20%7BText%3D%22Testing%20this%20Sonos%20speaker%22%2C%20Language%3D%22en%22%2C%20Volume%3D20%7D%2C%204)&_=1447398073950 tcp{client}: 0x10f8b98
2015-11-13 01:01:36.791   luup_log:0: ALTUI: runLua(luup.call_action("urn:micasaverde-com:serviceId:Sonos1", "Say", {Text="Testing this Sonos speaker", Language="en", Volume=20}, 4))
2015-11-13 01:01:36.791   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Sonos1.Say 
2015-11-13 01:01:36.791   luup_log:4: Sonos: debug: Say: Testing this Sonos speaker
2015-11-13 01:01:36.791   luup_log:4: Sonos: debug: TTS queueAlert for device 4
2015-11-13 01:01:36.792   luup_log:4: Sonos: debug: TTS server (ODX): device 4 language en text Testing this Sonos speaker
2015-11-13 01:01:36.957   luup_log:4: Sonos: debug: savePlaybackContexts: device=4 uuids=RINCON_000E587EA24201400
2015-11-13 01:01:36.957   luup_log:4: Sonos: debug: controlAnotherZone targetUUID=RINCON_000E587EA24201400 sourceDevice=4
2015-11-13 01:01:36.958   luup_log:4: Sonos: debug: controlAnotherZone result=4
2015-11-13 01:01:36.958   luup_log:4: Sonos: debug: refreshNow: device=4

Add device [5]. Ran TTS for device [4].

2015-11-13 01:05:03.225   openLuup.server:: /data_request?id=lr_ALTUI_LuaRunHandler&command=run_lua&lua=luup.call_action(%22urn%3Amicasaverde-com%3AserviceId%3ASonos1%22%2C%20%22Say%22%2C%20%7BText%3D%22Testing%20this%20Sonos%20speaker%22%2C%20Language%3D%22en%22%2C%20Volume%3D20%7D%2C%204)&_=1447398073969 tcp{client}: 0x1178268
2015-11-13 01:05:03.225   luup_log:0: ALTUI: runLua(luup.call_action("urn:micasaverde-com:serviceId:Sonos1", "Say", {Text="Testing this Sonos speaker", Language="en", Volume=20}, 4))
2015-11-13 01:05:03.226   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Sonos1.Say 
2015-11-13 01:05:03.226   luup_log:4: Sonos: debug: Say: Testing this Sonos speaker
2015-11-13 01:05:03.477   openLuup.context_switch:0:  ERROR: [string "device_5"]:1413: bad argument #1 to 'find' (string expected, got nil)
2015-11-13 01:05:03.478   luup_log:0: ALTUI: Evaluation of lua code returned: nil
2015-11-13 01:05:03.479   openLuup.server:: request completed (8 bytes, 1 chunks, 254 ms) tcp{client}: 0x1178268
2015-11-13 01:05:05.984   luup_log:4: Sonos: debug: refreshNow: device=4

And device [5] removed. Ran TTS for device [4].

2015-11-13 01:11:53.859   openLuup.server:: /data_request?id=lr_ALTUI_LuaRunHandler&command=run_lua&lua=luup.call_action(%22urn%3Amicasaverde-com%3AserviceId%3ASonos1%22%2C%20%22Say%22%2C%20%7BText%3D%22Testing%20this%20Sonos%20speaker%22%2C%20Language%3D%22en%22%2C%20Volume%3D20%7D%2C%204)&_=1447398698232 tcp{client}: 0x26bf158
2015-11-13 01:11:53.859   luup_log:0: ALTUI: runLua(luup.call_action("urn:micasaverde-com:serviceId:Sonos1", "Say", {Text="Testing this Sonos speaker", Language="en", Volume=20}, 4))
2015-11-13 01:11:53.860   luup.call_action:0: 4.urn:micasaverde-com:serviceId:Sonos1.Say 
2015-11-13 01:11:53.860   luup_log:4: Sonos: debug: Say: Testing this Sonos speaker
2015-11-13 01:11:53.860   luup_log:4: Sonos: debug: TTS queueAlert for device 4
2015-11-13 01:11:53.860   luup_log:4: Sonos: debug: TTS server (ODX): device 4 language en text Testing this Sonos speaker
2015-11-13 01:11:54.016   luup_log:4: Sonos: debug: savePlaybackContexts: device=4 uuids=RINCON_000E587EA24201400
2015-11-13 01:11:54.016   luup_log:4: Sonos: debug: controlAnotherZone targetUUID=RINCON_000E587EA24201400 sourceDevice=4
2015-11-13 01:11:54.016   luup_log:4: Sonos: debug: controlAnotherZone result=4
2015-11-13 01:11:54.016   luup_log:4: Sonos: debug: refreshNow: device=4