openLuup: AV plugins

akbooer · November 20, 2015, 11:54am

Progress in small steps: the “invalid chunk size” message comes from the LuaSocket module “socket.http”, because it thinks that the server hasn’t sent a content-length header. We can see from your latest test that it does. I can supply an instrumented version of that module to generate a more diagnostic error message, if you’re up for that.

mda · November 20, 2015, 3:25pm

Yes please !

Sent from my iPhone using Tapatalk

akbooer · November 20, 2015, 4:07pm

OK, well this will need to be refined, but for a start, here’s a new file to put into the /etc/cmh-ludl/openLuup/ directory.

You also need to change the line near the start of openLuup/server.lua…

from:

local http      = require "socket.http"

to:

local http      = require "openLuup.http"

For every incoming HTTP response it should write a line to the log file like this:

2015-11-20 16:04:46.434   luup_log:6: HTTP headers: {"content-type":"application\/json"}

Which version of openLuup are you running?

mda · November 20, 2015, 5:36pm

I believe it is 5.3. Should i update it to something else? Thanks.

akbooer · November 20, 2015, 5:45pm

Oh, gosh, well, yes, how about Release 6, if you can keep it separate from any working system you have?

It’s not on the master branch, but here. I’m using it full time.

https://github.com/akbooer/openLuup/tree/Release-6

mda · November 20, 2015, 5:48pm

will do when i get home tonight… having trouble w/ my remote access for some reason. thanks!

mda · November 21, 2015, 5:11am

[quote=“akbooer, post:85, topic:189395”]Oh, gosh, well, yes, how about Release 6, if you can keep it separate from any working system you have?

It’s not on the master branch, but here. I’m using it full time.

https://github.com/akbooer/openLuup/tree/Release-6[/quote]

i upgraded to version 6 and the latest AltUI.

I made the changes to server.lua to disable chunking and added the http.lua above and edited the line in server.lua to use it. Attached is the log. Also attached is server.lua so you can diff it from v6 and see what i did to it to make sure i did it right.

here are the new lines in the log:

mda$ grep 'HTTP headers' LuaUPnP.log 2015-11-20 21:06:07.036 luup_log:4: HTTP headers: { 2015-11-20 21:06:07.054 luup_log:4: HTTP headers: { 2015-11-20 21:06:07.172 luup_log:4: HTTP headers: { 2015-11-20 21:06:07.186 luup_log:4: HTTP headers: { 2015-11-20 21:06:07.206 luup_log:4: HTTP headers: {

Thanks!

==EDIT==
I also tried it with the server.lua from v6 (leaving chunking on) and just the change to use the new http.lua file. Attaching that log as well named “LuaUPnP-chunking_on.log.zip” in case there is anything useful in the comparison.

akbooer · November 21, 2015, 7:40am

The logs are a bit more informative than you might imagine since your grep only shows the opening brace of a multi-line structure. I’ll take a closer look!

akbooer · November 21, 2015, 8:42am

@mda

What I’m keen to see now it the result of this simple test, both the output and the log

local http = require "openLuup.http"
local a,b,c,d = http.request "http://192.168.1.125:49154/description.xml"
print (a,b,c,d)

Sorry this is a difficult one, which goes beyond the boundaries of any code I’ve written for openLuup! Thanks.

akbooer · November 21, 2015, 12:43pm

Just a little more on the log output: it’s all happily chatting away to 192.168.1.14:8080, but falls apart on the switch to 192.168.1.125:49153…

Is this a setup configuration problem? Do you not, in fact, mean 192.168.1.125:49154 ?

This has, by the way, absolutely nothing to do with whether the port 3480 server is sending in chunked mode or not - a red herring I dropped into the pool early on.

Do stick with Release 6.

mda · November 22, 2015, 6:10am

[quote=“akbooer, post:90, topic:189395”]Just a little more on the log output: it’s all happily chatting away to 192.168.1.14:8080, but falls apart on the switch to 192.168.1.125:49153…

Is this a setup configuration problem? Do you not, in fact, mean 192.168.1.125:49154 ?[/quote]

i do indeed mean 192.168.1.125:49153

the renderer does seem to change its port once in a while, odd i know – but i can assure you whenever i am testing i test from the browser first to make sure i am not chasing an old port. (on vera i have luup code that finds the renderer before it needs it so the port changing does not cause me any trouble).

mda · November 22, 2015, 6:21am

[quote=“akbooer, post:89, topic:189395”]@mda

What I’m keen to see now it the result of this simple test, both the output and the log

local http = require "openLuup.http"
local a,b,c,d = http.request "http://192.168.1.125:49154/description.xml"
print (a,b,c,d)

Sorry this is a difficult one, which goes beyond the boundaries of any code I’ve written for openLuup! Thanks.[/quote]

i changed it to http://192.168.1.125:49153/description.xml (port changed) because that is what the renderer is answering on now.

Openluup AltUI Lua Test Code returns:

[code]Return Result:
nil

Console Output:
nil invalid chunk size nil nil
[/code]

Log attached.

For comparison, in chrome that url http://192.168.1.125:49153/description.xml is returning:

This XML file does not appear to have any style information associated with it. The document tree is shown below. <root xmlns="urn:schemas-upnp-org:device-1-0"> <specVersion> <major>1</major> <minor>0</minor> </specVersion> <device> <deviceType>urn:schemas-upnp-org:device:MediaRenderer:1</deviceType> <presentationURL>/renderpres.html</presentationURL> <friendlyName>ROCKI_Sam</friendlyName> <manufacturer>Ivo Clarysse</manufacturer> <manufacturerURL>http://gmrender.nongnu.org/</manufacturerURL> <modelDescription>gmediarender 0.0.6</modelDescription> <modelName>Epitome</modelName> <modelURL>http://gmrender.nongnu.org/</modelURL> <UDN>uuid:5f9ec1b3-ed59-1900-4530-00117FB7DF48</UDN> <modelNumber>12</modelNumber> <dlna:X_DLNADOC xmlns:dlna="urn:schemas-dlna-org:device-1-0">DMR-1.50</dlna:X_DLNADOC> <iconList> <icon> <mimetype>image/png</mimetype> <width>64</width> <height>64</height> <depth>24</depth> <url>/upnp/grender-64x64.png</url> </icon> <icon> <mimetype>image/png</mimetype> <width>128</width> <height>128</height> <depth>24</depth> <url>/upnp/grender-128x128.png</url> </icon> </iconList> <serviceList> <service> <serviceType>urn:schemas-upnp-org:service:AVTransport:1</serviceType> <serviceId>urn:upnp-org:serviceId:AVTransport</serviceId> <SCPDURL>/upnp/rendertransportSCPD.xml</SCPDURL> <controlURL>/upnp/control/rendertransport1</controlURL> <eventSubURL>/upnp/event/rendertransport1</eventSubURL> </service> <service> <serviceType>urn:schemas-upnp-org:service:ConnectionManager:1</serviceType> <serviceId>urn:upnp-org:serviceId:ConnectionManager</serviceId> <SCPDURL>/upnp/renderconnmgrSCPD.xml</SCPDURL> <controlURL>/upnp/control/renderconnmgr1</controlURL> <eventSubURL>/upnp/event/renderconnmgr1</eventSubURL> </service> <service> <serviceType>urn:schemas-upnp-org:service:RenderingControl:1</serviceType> <serviceId>urn:upnp-org:serviceId:RenderingControl</serviceId> <SCPDURL>/upnp/rendercontrolSCPD.xml</SCPDURL> <controlURL>/upnp/control/rendercontrol1</controlURL> <eventSubURL>/upnp/event/rendercontrol1</eventSubURL> </service> </serviceList> </device> <URLBase>http://192.168.1.125:49153/</URLBase> </root>

mda · November 22, 2015, 6:29am

for comparison, i ran this on my vera:

local a,b = luup.inet.wget ("http://192.168.1.125:49153/description.xml") print (a,b)

and it returns:

[code]Results
No errors
Runtime: 13.2 ms
Code returned: nil

Print output
0

1
0

urn:schemas-upnp-org:device:MediaRenderer:1
/renderpres.html
ROCKI_Sam
Ivo Clarysse
http://gmrender.nongnu.org/
gmediarender 0.0.6
Epitome
http://gmrender.nongnu.org/
uuid:5f9ec1b3-ed59-1900-4530-00117FB7DF48
12
DMR-1.50

image/png
64
64
24
/upnp/grender-64x64.png

image/png
128
128
24
/upnp/grender-128x128.png

urn:schemas-upnp-org:service:AVTransport:1
urn:upnp-org:serviceId:AVTransport
/upnp/rendertransportSCPD.xml
/upnp/control/rendertransport1
/upnp/event/rendertransport1

urn:schemas-upnp-org:service:ConnectionManager:1
urn:upnp-org:serviceId:ConnectionManager
/upnp/renderconnmgrSCPD.xml
/upnp/control/renderconnmgr1
/upnp/event/renderconnmgr1

urn:schemas-upnp-org:service:RenderingControl:1
urn:upnp-org:serviceId:RenderingControl
/upnp/rendercontrolSCPD.xml
/upnp/control/rendercontrol1
/upnp/event/rendercontrol1

http://192.168.1.125:49153/

Code
1 local a,b = luup.inet.wget (“http://192.168.1.125:49153/description.xml”)
2 print (a,b)
[/code]

Here is a screen shot of the renderer selected in my vera and the 4 renderers the DLNA plugin on vera finds (vs the 1 it finds on openLuup).

–EDIT–

Here are the DLNA related log entries for that rendered on my vera when i plan an mp3 file on it:

06 11/21/15 22:18:31.177 Device_Variable::m_szValue_set device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 variable: DebugLogs was: 0 now: 1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x3032d680> 08 11/21/15 22:18:35.973 JobHandler_LuaUPnP::HandleActionRequest device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 action: SelectDMRDevice <0x3032d680> 08 11/21/15 22:18:35.974 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:dlna-org:serviceId:DLNAMediaController1 <0x3032d680> 06 11/21/15 22:18:35.975 Device_Variable::m_szValue_set device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 variable: DescriptionURL was: http://192.168.1.125:49153/description.xml now: http://192.168.1.125:49153/description.xml #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x3032d680> 06 11/21/15 22:18:36.472 Device_Variable::m_szValue_set device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 variable: MinVolume was: 0 now: 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x3032d680> 06 11/21/15 22:18:36.472 Device_Variable::m_szValue_set device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 variable: MaxVolume was: 100 now: 100 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x3032d680> 08 11/21/15 22:19:30.274 JobHandler_LuaUPnP::HandleActionRequest device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 action: Play <0x3032d680> 08 11/21/15 22:19:30.275 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:dlna-org:serviceId:DLNAMediaController1 <0x3032d680> 50 11/21/15 22:19:30.277 luup_log:158: DLNA: debug: service.__index: Accessing non-existing function Stop <0x3032d680> 50 11/21/15 22:19:30.277 luup_log:158: DLNA: debug: Stop('http://192.168.1.125:49153/upnp/control/rendertransport1', 'urn:schemas-upnp-org:service:AVTransport:1') Called with parameter count=1 <0x3032d680> 50 11/21/15 22:19:30.278 luup_log:158: DLNA: debug: UPnP_request: url=[http://192.168.1.125:49153/upnp/control/rendertransport1], body=[<?xml version="1.0" encoding="utf-8"?> 50 11/21/15 22:19:30.300 luup_log:158: DLNA: 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> 50 11/21/15 22:19:30.301 luup_log:158: DLNA: debug: service.__index: Accessing non-existing function SetAVTransportURI <0x3032d680> 50 11/21/15 22:19:30.302 luup_log:158: DLNA: debug: SetAVTransportURI('http://192.168.1.125:49153/upnp/control/rendertransport1', 'urn:schemas-upnp-org:service:AVTransport:1') Called with parameter count=1 <0x3032d680> 50 11/21/15 22:19:30.303 luup_log:158: DLNA: debug: UPnP_request: url=[http://192.168.1.125:49153/upnp/control/rendertransport1], body=[<?xml version="1.0" encoding="utf-8"?> <u:SetAVTransportURI xmlns:u="urn:schemas-upnp-org:service:AVTransport:1"><InstanceID>0</InstanceID><CurrentURI>http://192.168.1.12/doorbell.mp3</CurrentURI><CurrentURIMetaData><DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/"><item id="DLNA" parentID="-1" restricted="1"><dc:title>doorbell.mp3</dc:title><upnp:class>object.item</upnp:class></item></DIDL-Lite></CurrentURIMetaData></u:SetAVTransportURI> 50 11/21/15 22:19:30.660 luup_log:158: DLNA: 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> 50 11/21/15 22:19:30.662 luup_log:158: DLNA: debug: service.__index: Accessing non-existing function Play <0x3032d680> 50 11/21/15 22:19:30.663 luup_log:158: DLNA: debug: Play('http://192.168.1.125:49153/upnp/control/rendertransport1', 'urn:schemas-upnp-org:service:AVTransport:1') Called with parameter count=1 <0x3032d680> 50 11/21/15 22:19:30.664 luup_log:158: DLNA: debug: UPnP_request: url=[http://192.168.1.125:49153/upnp/control/rendertransport1], body=[<?xml version="1.0" encoding="utf-8"?> 50 11/21/15 22:19:30.931 luup_log:158: DLNA: 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> 50 11/21/15 22:19:30.932 luup_log:158: DLNA: debug: refreshNow: start <0x3032d680> 08 11/21/15 22:19:31.398 JobHandler_LuaUPnP::HandleActionRequest device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 action: NotifyAVTransportChange <0x319e4680> 08 11/21/15 22:19:31.398 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:dlna-org:serviceId:DLNAMediaController1 <0x319e4680> 50 11/21/15 22:19:31.402 luup_log:158: DLNA: debug: handleAVTransportChange for device 158 value <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportState val="PLAYING"/></InstanceID></Event> <0x2af22000> 50 11/21/15 22:19:31.405 luup_log:158: DLNA: debug: GetPositionInfo('http://192.168.1.125:49153/upnp/control/rendertransport1', 'urn:schemas-upnp-org:service:AVTransport:1') Called with parameter count=1 <0x2af22000> 50 11/21/15 22:19:31.405 luup_log:158: DLNA: debug: UPnP_request: url=[http://192.168.1.125:49153/upnp/control/rendertransport1], body=[<?xml version="1.0" encoding="utf-8"?> 50 11/21/15 22:19:31.487 luup_log:158: DLNA: 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> 08 11/21/15 22:19:34.070 JobHandler_LuaUPnP::HandleActionRequest device: 158 service: urn:dlna-org:serviceId:DLNAMediaController1 action: NotifyAVTransportChange <0x30fcb680> 08 11/21/15 22:19:34.070 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:dlna-org:serviceId:DLNAMediaController1 <0x30fcb680> 50 11/21/15 22:19:34.074 luup_log:158: DLNA: debug: handleAVTransportChange for device 158 value <Event xmlns = "urn:schemas-upnp-org:metadata-1-0/AVT/"><InstanceID val="0"><TransportState val="STOPPED"/></InstanceID></Event> <0x2af22000> 50 11/21/15 22:19:34.077 luup_log:158: DLNA: debug: GetPositionInfo('http://192.168.1.125:49153/upnp/control/rendertransport1', 'urn:schemas-upnp-org:service:AVTransport:1') Called with parameter count=1 <0x2af22000> 50 11/21/15 22:19:34.098 luup_log:158: DLNA: debug: UPnP_request: url=[http://192.168.1.125:49153/upnp/control/rendertransport1], body=[<?xml version="1.0" encoding="utf-8"?> 50 11/21/15 22:19:34.127 luup_log:158: DLNA: 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>

akbooer · November 22, 2015, 10:32am

OK, I’ll try not to get so excited. Anyway, this is a really useful part of the log:

2015-11-21 22:14:37.183   luup_log:0: HTTP headers: {
  "connection":"close",
  "content-type":"text\/xml",
  "date":"Sun, 22 Nov 2015 06:14:39 GMT",
  "last-modified":"Fri, 20 Nov 2015 14:30:59 GMT",
  "server":"Linux\/2.6.28.3, UPnP\/1.0, Portable SDK for UPnP devices\/1.6.6",
  "transfer-encoding":"chunked",
  "x-user-agent":"redsonic"}

It shows that your DLNA port:49153 (or whatever) server is sending chunked encoding. The socket.http module is handling this incorrectly.

Here’s both extra diagnostics and a possible fix to try on the same, short test.

mda · November 22, 2015, 8:01pm

Thanks, i placed this file in my openluup directory and ran openluup (I did not do a reset, just ./openLuup_reload). The fix did not work

The plugin still does not discover the other renders or work when i manually put the renderer URL in. The test code returns:

[code]Lua Test Code:
local http = require “openLuup.http”
local a,b,c,d = http.request “http://192.168.1.125:49153/description.xml”
print (a,b,c,d)

Return Result:
nil

Console Output:
nil invalid chunk size nil nil[/code]

Log attached. (i notice i don’t see any ‘HTTP headers’ entries in the log now, though i have not changed by server.lua, it still has local http = require “openLuup.http”)

Thanks.

mda · November 24, 2015, 3:38pm

@akbooer Do you have any more ideas to try or am I out of luck here? Thanks.

Sent from my iPhone using Tapatalk

akbooer · November 24, 2015, 4:52pm

Yes, lots, but not much time this week. We can fix this.

mda · November 24, 2015, 5:11pm

thanks ! standing by whenever you have time, no rush.

akbooer · November 26, 2015, 10:36am

So try this. It’s a stand-alone program which you just run with Lua and it outputs diagnostics to the terminal.

You may need to change the last line to reflect whatever port number your system thinks it’s using at the moment.

Interested, of course, in what it says.

mda · November 27, 2015, 12:52am

Thanks. the output is:

[code]mda$ lua5.1 /Users/mda/Downloads/http_test.lua
— status —
HTTP/1.1 200 OK
— headers —
TRANSFER-ENCODING: chunked
CONTENT-TYPE: text/xml
DATE: Fri, 27 Nov 2015 00:48:46 GMT
LAST-MODIFIED: Fri, 20 Nov 2015 14:30:59 GMT
SERVER: Linux/2.6.28.3, UPnP/1.0, Portable SDK for UPnP devices/1.6.6
X-User-Agent: redsonic
CONNECTION: close

— chunk —

<?xml version="1.0"?> nil

lua5.1: /Users/mda/Downloads/http_test.lua:80: bad argument #1 to ‘tonumber’ (string expected, got nil)
stack traceback:
[C]: in function ‘request’
/Users/mda/Downloads/http_test.lua:377: in main chunk
[C]: ?
[/code]

The URL in the file is correct, curl returns:

[code]mda$ curl 192.168.1.125:49153/description.xml

<?xml version="1.0"?> 1 0 urn:schemas-upnp-org:device:MediaRenderer:1 /renderpres.html ROCKI_Sam Ivo Clarysse http://gmrender.nongnu.org/ gmediarender 0.0.6 Epitome http://gmrender.nongnu.org/ uuid:5f9ec1b3-ed59-1900-4530-00117FB7DF48 12 DMR-1.50 image/png 64 64 24 /upnp/grender-64x64.png image/png 128 128 24 /upnp/grender-128x128.png urn:schemas-upnp-org:service:AVTransport:1 urn:upnp-org:serviceId:AVTransport /upnp/rendertransportSCPD.xml /upnp/control/rendertransport1 /upnp/event/rendertransport1 urn:schemas-upnp-org:service:ConnectionManager:1 urn:upnp-org:serviceId:ConnectionManager /upnp/renderconnmgrSCPD.xml /upnp/control/renderconnmgr1 /upnp/event/renderconnmgr1 urn:schemas-upnp-org:service:RenderingControl:1 urn:upnp-org:serviceId:RenderingControl /upnp/rendercontrolSCPD.xml /upnp/control/rendercontrol1 /upnp/event/rendercontrol1 http://192.168.1.125:49153/ [/code]