svn-1696 on NSLU2: "Out of memory" when using WMP

[Anonymous]

Hi

Sometimes the mt-daap crashes when trying to listen to files using the windows media player (by directly accessing the http://server:3680/rsp/stream/xxxx urls).
Even after restarting the daap, the problem remains.. If using RealPlayer or trying to download with IExplorer, it is working all the time.

The last log entry:

2008-01-09 16:31:04 (00004000): Firefly Version svn-1696: Starting with debuglevel 2
2008-01-09 16:31:04 (00004000): Plugin loaded: ssc-script/svn-1696
2008-01-09 16:31:04 (00004000): Plugin loaded: daap/svn-1696
2008-01-09 16:31:04 (00004000): Plugin loaded: rsp/svn-1696
2008-01-09 16:31:04 (00004000): Starting rendezvous daemon
2008-01-09 16:31:04 (00004000): Starting signal handler
2008-01-09 16:31:04 (00004000): Initializing database
2008-01-09 16:31:29 (00004000): Starting web server from /opt/share/mt-daapd/admin-root on port 3689
2008-01-09 16:31:29 (00004000): Registering rendezvous names
2008-01-09 16:31:29 (00004000): Serving 7367 songs. Startup complete in 25 seconds
2008-01-09 16:33:40 (0000c003): Session 0: Streaming file ’06 – Lullaby Of Birdland.mp3′ to 84.227.131.43 (offset 0)
2008-01-09 16:33:42 (0000c003): Write error: Connection reset by peer
2008-01-09 16:33:42 (00014003): Session 0: Streaming file ’05 – Tea For Two.mp3′ to 84.227.131.43 (offset 0)
2008-01-09 16:33:44 (00014003): Write error: Connection reset by peer
2008-01-09 16:33:45 (00020003): Session 0: Streaming file ’05 – Tea For Two.mp3′ to 84.227.131.43 (offset 0)
2008-01-09 16:36:59 (00028003): Session 0: Streaming file ’06 – Lullaby Of Birdland.mp3′ to 84.227.131.43 (offset 0)
2008-01-09 16:41:35 (00040003): Session 0: Streaming file ’07 – As Time Goes By.mp3′ to 84.227.131.43 (offset 0)
2008-01-09 16:43:35 (00054003): Thread 19: Out of memory
2008-01-09 16:43:35: Aborting

[Anonymous]

just for completeness, I’m adding the extended logfiles with loglevel 9.

When using Windows Media Player:

2008-01-09 20:55:52 (00004002): Got listen socket 11
2008-01-09 20:55:52 (00008003): Thread 0:
2008-01-09 20:55:52 (00008003): Request: GET /rsp/stream/6471 HTTP/1.1
2008-01-09 20:55:52 (00008003): Thread 0: Read: Accept: */*
2008-01-09 20:55:52 (00008003): Thread 0: Adding header *Accept=*/**
2008-01-09 20:55:52 (00008003): Added *Accept=*/**
2008-01-09 20:55:52 (00008003): Thread 0: Read: User-Agent: NSPlayer/11.0.5721.5145
2008-01-09 20:55:52 (00008003): Thread 0: Adding header *User-Agent=NSPlayer/11.0.5721.5145*
2008-01-09 20:55:52 (00008003): Added *User-Agent=NSPlayer/11.0.5721.5145*
2008-01-09 20:55:52 (00008003): Thread 0: Read: Host: vpn.swissmediaportal.ch
2008-01-09 20:55:52 (00008003): Thread 0: Adding header *Host=vpn.swissmediaportal.ch*
2008-01-09 20:55:52 (00008003): Added *Host=vpn.swissmediaportal.ch*
2008-01-09 20:55:52 (00008003): Thread 0: Read: X-Accept-Authentication: Negotiate, NTLM, Digest, Basic
2008-01-09 20:55:52 (00008003): Thread 0: Adding header *X-Accept-Authentication=Negotiate, NTLM, Digest, Basic*
2008-01-09 20:55:52 (00008003): Added *X-Accept-Authentication=Negotiate, NTLM, Digest, Basic*
2008-01-09 20:55:52 (00008003): Thread 0: Read: Pragma: version11-enabled=1
2008-01-09 20:55:52 (00008003): Thread 0: Adding header *Pragma=version11-enabled=1*
2008-01-09 20:55:52 (00008003): Added *Pragma=version11-enabled=1*
2008-01-09 20:55:52 (00008003): Thread 0: Read: Pragma: no-cache,rate=1.000,stream-time=0,stream-offset=0:0,packet-num=4294967295,max-duration=0
2008-01-09 20:55:52 (00008003): Thread 0: Adding header *Pragma=no-cache,rate=1.000,stream-time=0,stream-offset=0:0,packet-num=4294967295,max-duration=0*
2008-01-09 20:55:52 (00008003): Updating Pragma from version11-enabled=1 to no-cache,rate=1.000,stream-time=0,stream-offset=0:0,packet-num=4294967295,max-duration=0
2008-01-09 20:55:52 (00008003): Thread 0: Out of memory
2008-01-09 20:55:52: Aborting

When using Real Player:

2008-01-09 20:58:00 (00004002): Got listen socket 11
2008-01-09 20:58:00 (00010003): Thread 2:
2008-01-09 20:58:00 (00010003): Request: GET /rsp/stream/6471 HTTP/1.1
2008-01-09 20:58:00 (00010003): Thread 2: Read: Accept: */*
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Accept=*/**
2008-01-09 20:58:00 (00010003): Added *Accept=*/**
2008-01-09 20:58:00 (00010003): Thread 2: Read: User-Agent: RMA/1.0 (compatible; RealMedia)
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *User-Agent=RMA/1.0 (compatible; RealMedia)*
2008-01-09 20:58:00 (00010003): Added *User-Agent=RMA/1.0 (compatible; RealMedia)*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Icy-MetaData: 1
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Icy-MetaData=1*
2008-01-09 20:58:00 (00010003): Added *Icy-MetaData=1*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Bandwidth: 10485800
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Bandwidth=10485800*
2008-01-09 20:58:00 (00010003): Added *Bandwidth=10485800*
2008-01-09 20:58:00 (00010003): Thread 2: Read: ClientID: WinNT_5.1_6.0.14.748_RealPlayer_R41DED_de_UNK
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *ClientID=WinNT_5.1_6.0.14.748_RealPlayer_R41DED_de_UNK*
2008-01-09 20:58:00 (00010003): Added *ClientID=WinNT_5.1_6.0.14.748_RealPlayer_R41DED_de_UNK*
2008-01-09 20:58:00 (00010003): Thread 2: Read: GUID: 00000000-0000-0000-0000-000000000000
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *GUID=00000000-0000-0000-0000-000000000000*
2008-01-09 20:58:00 (00010003): Added *GUID=00000000-0000-0000-0000-000000000000*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Language: de, de, *
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Language=de, de, **
2008-01-09 20:58:00 (00010003): Added *Language=de, de, **
2008-01-09 20:58:00 (00010003): Thread 2: Read: RegionData: 23456
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *RegionData=23456*
2008-01-09 20:58:00 (00010003): Added *RegionData=23456*
2008-01-09 20:58:00 (00010003): Thread 2: Read: SupportsMaximumASMBandwidth: 1
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *SupportsMaximumASMBandwidth=1*
2008-01-09 20:58:00 (00010003): Added *SupportsMaximumASMBandwidth=1*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Connection: Keep-Alive
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Connection=Keep-Alive*
2008-01-09 20:58:00 (00010003): Added *Connection=Keep-Alive*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Host: vpn.swissmediaportal.ch:3689
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Host=vpn.swissmediaportal.ch:3689*
2008-01-09 20:58:00 (00010003): Added *Host=vpn.swissmediaportal.ch:3689*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Accept-Language: de, de, *
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Accept-Language=de, de, **
2008-01-09 20:58:00 (00010003): Added *Accept-Language=de, de, **
2008-01-09 20:58:00 (00010003): Thread 2: Read: Accept-Encoding: gzip
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Accept-Encoding=gzip*
2008-01-09 20:58:00 (00010003): Added *Accept-Encoding=gzip*
2008-01-09 20:58:00 (00010003): Thread 2: Read: Range:bytes=8601-
2008-01-09 20:58:00 (00010003): Thread 2: Adding header *Range=bytes=8601-*
2008-01-09 20:58:00 (00010003): Added *Range=bytes=8601-*
2008-01-09 20:58:00 (00010003): Thread 2: Read:
2008-01-09 20:58:00 (00010003): Thread 2: Headers parsed!
2008-01-09 20:58:00 (00010003): Checking to see if connection matches close
2008-01-09 20:58:00 (00010003): And it does NOT
2008-01-09 20:58:00 (00010003): Thread 2: Connection type HTTP/1.1
: Connection: persist
2008-01-09 20:58:00 (00010003): Thread 2: Original URI: /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Thread 2: Translated URI: /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Thread 2: Preparing to find handler
2008-01-09 20:58:00 (00010003): Checking /rsp/stream/6471 against handler for /
2008-01-09 20:58:00 (00010003): Thread 2: URI Match!
2008-01-09 20:58:00 (00010003): Thread 2: Time is 1199908680 seconds after epoch
2008-01-09 20:58:00 (00010003): Thread 2: Setting time header
2008-01-09 20:58:00 (00010003): Added *Date=Wed, 9 Jan 2008 19:58:00 GMT*
2008-01-09 20:58:00 (00010003): Added *Connection=keep-alive*
2008-01-09 20:58:00 (00010003): Added *Server=mt-daapd/svn-1696*
2008-01-09 20:58:00 (00010003): Added *Content-Type=text/html*
2008-01-09 20:58:00 (00010003): Added *Content-Language=en_us*
2008-01-09 20:58:00 (00010003): Thread 2: Using non-default handler
2008-01-09 20:58:00 (00010003): in main_auth
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Dispatching auth for /rsp/stream/6471 to plugin
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Dispatching /rsp/stream/6471 to rsp/svn-1696
2008-01-09 20:58:00 (00010003): Checking if pw required for /rsp/stream/6471 as user
2008-01-09 20:58:00 (00010003): Nope
2008-01-09 20:58:00 (00010003): in main_handler
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Dispatching /rsp/stream/6471 to plugin
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Checking url /rsp/stream/6471
2008-01-09 20:58:00 (00010003): Dispatching /rsp/stream/6471 to rsp/svn-1696
2008-01-09 20:58:00 (00010003): Getting uri…
2008-01-09 20:58:00 (00010003): Mallocing privinfo…
2008-01-09 20:58:00 (00010003): Tokenizing url
2008-01-09 20:58:00 (00010003): Found 5 elements
2008-01-09 20:58:00 (00010003): Checking reponse 0
2008-01-09 20:58:00 (00010003): Checking reponse 1
2008-01-09 20:58:00 (00010003): Checking reponse 2
2008-01-09 20:58:00 (00010003): Checking reponse 3
2008-01-09 20:58:00 (00010003): Checking reponse 4
2008-01-09 20:58:00 (00010003): Found it! Index: 4
2008-01-09 20:58:00 (00010003): Executing: select * from songs where id=6471
2008-01-09 20:58:00 (00010003): Creating new db handle
2008-01-09 20:58:00 (00010003): Opening file:///media/sdb1/musik/Sounds/B/Blunt+James/All+the+lost+souls/01-james_blunt-1973.mp3
2008-01-09 20:58:00 (00010003): Checking handler for file
2008-01-09 20:58:00 (00010003): opening /media/sdb1/musik/Sounds/B/Blunt James/All the lost souls/01-james_blunt-1973.mp3
2008-01-09 20:58:00 (00010003): Thread 2: Length of file (remaining): 6277123
2008-01-09 20:58:00 (00010003): Updating Content-Type from text/html to audio/mp3
2008-01-09 20:58:00 (00010003): Added *Content-Length=6277123*
2008-01-09 20:58:00 (00010003): Updating Connection from keep-alive to Close
2008-01-09 20:58:00 (00010003): Added *Content-Range=bytes 8601-6285724/6285725*
2008-01-09 20:58:00 (00010003): Emitting reponse header Content-Range: bytes 8601-6285724/6285725
2008-01-09 20:58:00 (00010003): Emitting reponse header Content-Length: 6277123
2008-01-09 20:58:00 (00010003): Emitting reponse header Content-Language: en_us
2008-01-09 20:58:00 (00010003): Emitting reponse header Content-Type: audio/mp3
2008-01-09 20:58:00 (00010003): Emitting reponse header Server: mt-daapd/svn-1696
2008-01-09 20:58:00 (00010003): Emitting reponse header Connection: Close
2008-01-09 20:58:00 (00010003): Emitting reponse header Date: Wed, 9 Jan 2008 19:58:00 GMT
2008-01-09 20:58:00 (00010003): Entering config_set_status
2008-01-09 20:58:00 (00010003): Exiting config_set_status
2008-01-09 20:58:00 (00010003): Session 0: Streaming file ’01-james_blunt-1973.mp3′ to 84.227.131.43 (offset 8601)
2008-01-09 20:58:00 (00010003): Seeking to offset 8601
2008-01-09 20:58:06 (00010003): Write error: Broken pipe
2008-01-09 20:58:06 (00010003): Error copying file to remote…
2008-01-09 20:58:06 (00010003): Entering config_set_status
2008-01-09 20:58:06 (00010003): Exiting config_set_status
2008-01-09 20:58:06 (00010003): Thread 2: Terminating
2008-01-09 20:58:06 (00010003): Thread 2: Freeing request headers
2008-01-09 20:58:06 (00010003): Thread 2: Freeing response headers
2008-01-09 20:58:06 (00010003): Thread 2: Freeing request vars
2008-01-09 20:58:06 (00010003): Thread 2: Closing fd
2008-01-09 20:58:06 (00010003): With thread 2 exiting, 0 are still running

Maybe this information helps somebody…

[rpedde]

@swissy wrote:

Hi

Sometimes the mt-daap crashes when trying to listen to files using the windows media player (by directly accessing the http://server:3680/rsp/stream/xxxx urls).
Even after restarting the daap, the problem remains.. If using RealPlayer or trying to download with IExplorer, it is working all the time.

Version of mt-daapd?

[stretch]

Hi Ron,

swissy is using svn-1696 on an NSLU2. It’s in the subject line.

[Anonymous]

exactly, I’m using svn-1696 on the NSLU2 (SlugOS/BE).

I just found out, that the “Out of memory” does not happen, if “.mp3” is appended to the link, for example

http://server:3689/rsp/stream/1234.mp3

instead of just

http://server:3689/rsp/stream/1234

The logfile for such a link using WMP looks then like this:

2008-01-10 09:18:48 (00004002): Got listen socket 11
2008-01-10 09:18:48 (00034003): Thread 11:
2008-01-10 09:18:48 (00034003): Request: GET /rsp/stream/6471.mp3 HTTP/1.1
2008-01-10 09:18:48 (00034003): Thread 11: Read: Accept: */*
2008-01-10 09:18:48 (00034003): Thread 11: Adding header *Accept=*/**
2008-01-10 09:18:48 (00034003): Added *Accept=*/**
2008-01-10 09:18:48 (00034003): Thread 11: Read: User-Agent: NSPlayer/11.0.5721.5145 WMFSDK/11.0
2008-01-10 09:18:48 (00034003): Thread 11: Adding header *User-Agent=NSPlayer/11.0.5721.5145 WMFSDK/11.0*
2008-01-10 09:18:48 (00034003): Added *User-Agent=NSPlayer/11.0.5721.5145 WMFSDK/11.0*
2008-01-10 09:18:48 (00034003): Thread 11: Read: UA-CPU: x86
2008-01-10 09:18:48 (00034003): Thread 11: Adding header *UA-CPU=x86*
2008-01-10 09:18:48 (00034003): Added *UA-CPU=x86*
2008-01-10 09:18:48 (00034003): Thread 11: Read: Accept-Encoding: gzip, deflate
2008-01-10 09:18:48 (00034003): Thread 11: Adding header *Accept-Encoding=gzip, deflate*
2008-01-10 09:18:48 (00034003): Added *Accept-Encoding=gzip, deflate*
2008-01-10 09:18:48 (00034003): Thread 11: Read: Host: vpn.swissmediaportal.ch:3689
2008-01-10 09:18:48 (00034003): Thread 11: Adding header *Host=vpn.swissmediaportal.ch:3689*
2008-01-10 09:18:48 (00034003): Added *Host=vpn.swissmediaportal.ch:3689*
2008-01-10 09:18:48 (00034003): Thread 11: Read: Connection: Keep-Alive
2008-01-10 09:18:48 (00034003): Thread 11: Adding header *Connection=Keep-Alive*
2008-01-10 09:18:48 (00034003): Added *Connection=Keep-Alive*
2008-01-10 09:18:48 (00034003): Thread 11: Read:
2008-01-10 09:18:48 (00034003): Thread 11: Headers parsed!
2008-01-10 09:18:48 (00034003): Checking to see if connection matches close
2008-01-10 09:18:48 (00034003): And it does NOT
2008-01-10 09:18:48 (00034003): Thread 11: Connection type HTTP/1.1
: Connection: persist
2008-01-10 09:18:48 (00034003): Thread 11: Original URI: /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Thread 11: Translated URI: /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Thread 11: Preparing to find handler
2008-01-10 09:18:48 (00034003): Checking /rsp/stream/6471.mp3 against handler for /
2008-01-10 09:18:48 (00034003): Thread 11: URI Match!
2008-01-10 09:18:48 (00034003): Thread 11: Time is 1199953128 seconds after epoch
2008-01-10 09:18:48 (00034003): Thread 11: Setting time header
2008-01-10 09:18:48 (00034003): Added *Date=Thu, 10 Jan 2008 08:18:48 GMT*
2008-01-10 09:18:48 (00034003): Added *Connection=keep-alive*
2008-01-10 09:18:48 (00034003): Added *Server=mt-daapd/svn-1696*
2008-01-10 09:18:48 (00034003): Added *Content-Type=text/html*
2008-01-10 09:18:48 (00034003): Added *Content-Language=en_us*
2008-01-10 09:18:48 (00034003): Thread 11: Using non-default handler
2008-01-10 09:18:48 (00034003): in main_auth
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Dispatching auth for /rsp/stream/6471.mp3 to plugin
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Dispatching /rsp/stream/6471.mp3 to rsp/svn-1696
2008-01-10 09:18:48 (00034003): Checking if pw required for /rsp/stream/6471.mp3 as user
2008-01-10 09:18:48 (00034003): Nope
2008-01-10 09:18:48 (00034003): in main_handler
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Dispatching /rsp/stream/6471.mp3 to plugin
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Checking url /rsp/stream/6471.mp3
2008-01-10 09:18:48 (00034003): Dispatching /rsp/stream/6471.mp3 to rsp/svn-1696
2008-01-10 09:18:48 (00034003): Getting uri…
2008-01-10 09:18:48 (00034003): Mallocing privinfo…
2008-01-10 09:18:48 (00034003): Tokenizing url
2008-01-10 09:18:48 (00034003): Found 5 elements
2008-01-10 09:18:48 (00034003): Checking reponse 0
2008-01-10 09:18:48 (00034003): Checking reponse 1
2008-01-10 09:18:48 (00034003): Checking reponse 2
2008-01-10 09:18:48 (00034003): Checking reponse 3
2008-01-10 09:18:48 (00034003): Checking reponse 4
2008-01-10 09:18:48 (00034003): Found it! Index: 4
2008-01-10 09:18:48 (00034003): Executing: select * from songs where id=6471
2008-01-10 09:18:48 (00034003): Creating new db handle
2008-01-10 09:18:48 (00034003): Opening file:///media/sdb1/musik/Sounds/B/Blunt+James/All+the+lost+souls/01-james_blunt-1973.mp3
2008-01-10 09:18:48 (00034003): Checking handler for file
2008-01-10 09:18:48 (00034003): opening /media/sdb1/musik/Sounds/B/Blunt James/All the lost souls/01-james_blunt-1973.mp3
2008-01-10 09:18:48 (00034003): Thread 11: Length of file (remaining): 6285724
2008-01-10 09:18:48 (00034003): Updating Content-Type from text/html to audio/mp3
2008-01-10 09:18:48 (00034003): Added *Content-Length=6285724*
2008-01-10 09:18:48 (00034003): Updating Connection from keep-alive to Close
2008-01-10 09:18:48 (00034003): Emitting reponse header Content-Length: 6285724
2008-01-10 09:18:48 (00034003): Emitting reponse header Content-Language: en_us
2008-01-10 09:18:48 (00034003): Emitting reponse header Content-Type: audio/mp3
2008-01-10 09:18:48 (00034003): Emitting reponse header Server: mt-daapd/svn-1696
2008-01-10 09:18:48 (00034003): Emitting reponse header Connection: Close
2008-01-10 09:18:48 (00034003): Emitting reponse header Date: Thu, 10 Jan 2008 08:18:48 GMT
2008-01-10 09:18:48 (00034003): Entering config_set_status
2008-01-10 09:18:48 (00034003): Exiting config_set_status
2008-01-10 09:18:48 (00034003): Session 0: Streaming file ’01-james_blunt-1973.mp3′ to 84.226.32.119 (offset 0)

Quite strange behavior, I think..

[mas]

Not too long ago I posted a similar behavior, not with WMP but with VLC/winamp etc.

That mt-daapd does certainly not like the way some clients attempt to access it. Speaking of latest nightly of course.

[rpedde]

@mas wrote:

Not too long ago I posted a similar behavior, not with WMP but with VLC/winamp etc.

That mt-daapd does certainly not like the way some clients attempt to access it. Speaking of latest nightly of course.

Hrm… really should do that. 🙂

grumble.

— Ron

[Author]

Posts