Bug 2795 - Problem with mp3 stream from LastFM on 6.5
: Problem with mp3 stream from LastFM on 6.5
Status: RESOLVED FIXED
Product: Logitech Media Server
Classification: Unclassified
Component: Streaming To SlimServer
: 6.5b1
: PC Windows XP
: P2 major (vote)
: ---
Assigned To: Dan Sully
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2006-01-08 09:39 UTC by James Craig
Modified: 2006-01-28 01:24 UTC (History)
1 user (show)

See Also:
Category: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description James Craig 2006-01-08 09:39:05 UTC
LastFM plugin makes SlimServer hit 100% CPU usage once connected to LastFM radio stream from Softsqueeze, and playback never starts. Working fine in 6.2.

Any idea what flags would be useful to debug?

This is what I get in the log with d_remotestream:

2006-01-08 17:30:48.2068 Opening connection to http://streamer1.audioscrobbler.com/last.mp3?Session=aa630ee5e2f407883909
6dad7c57b534: [streamer1.audioscrobbler.com on port 80 with path /last.mp3?Session=aa630ee5e2f4078839096dad7c57b534 with
 timeout 5]
2006-01-08 17:30:48.2269 Request:
GET /last.mp3?Session=aa630ee5e2f4078839096dad7c57b534 HTTP/1.0
Accept: */*
Cache-Control: no-cache
User-Agent: iTunes/4.7.1 (Windows; N; Windows XP; 586; EN; cp1252) SlimServer/6.5b1/5567
Icy-MetaData: 1
Connection: close
Host: streamer1.audioscrobbler.com


2006-01-08 17:30:48.2637 Response: HTTP/1.0 200 OK

2006-01-08 17:30:48.2660 header: Server: last.fm Streaming Server
2006-01-08 17:30:48.2667 header: Content-type: audio/mpeg
2006-01-08 17:30:48.2675 opened stream!
Comment 1 James Craig 2006-01-25 13:32:34 UTC
I found what the cause of this is. Seems when I set a timer, SS gets stuck. 
This is the output with d_timers:

2006-01-25 21:24:43.5558 LastFM: Setting timer for 30 seconds for 25:81:b0:4a:7c:0d
2006-01-25 21:24:43.5565 settimer Normal: CODE(0x3b8b358), now: 1138224283.5565, time: 1138224313.55648
2006-01-25 21:24:44.3558 select_time - idleStreams: 0
2006-01-25 21:24:44.3564 blocked checking normal timers - already processing a normal timer!
2006-01-25 21:24:44.3569 select_time - idleStreams: 0
2006-01-25 21:24:44.3573 blocked checking normal timers - already processing a normal timer!
2006-01-25 21:24:44.3577 select_time - idleStreams: 0

The last 2 messages just keep coming.
But my timer never got called, so what's going on?
Comment 2 KDF 2006-01-25 13:42:22 UTC
adrian, any thoughts here?  Is there a good way to dig up which timer is being stuck?
Comment 3 Adrian Smith 2006-01-25 13:47:25 UTC
Put a bt() into the code in Timers.pm which prints the error message it should give you the stack which includes which timer is currently being processed.

This code was there to avoid reentrancy issues of timers firing within timers.  As long as timers always return it is fine.  If you need a timer to run inside another timer, high priority timers can run inside normal ones (so screen animation continues)
Comment 4 Adrian Smith 2006-01-25 14:14:24 UTC
Should also say this has been there since 6.0 ish (when I started hacking the server) so I doubt it is the check itself - it could be an impact of the updates to Timers.pm.  Send me a way to prove the problem and I can look at it...
Comment 5 James Craig 2006-01-25 23:49:28 UTC
Backtrace:
2006-01-26 07:45:19.6506 Backtrace:

   frame 0: Slim::Utils::Timers::checkTimers (slimserver.pl line 659)
   frame 1: main::idleStreams (C:/Program Files/SlimServer6.5/server/Slim/Formats/RemoteStream.pm line 212)
   frame 2: Slim::Formats::RemoteStream::content (C:/Program Files/SlimServer6.5/server/Slim/Utils/Scan.pm line 656)
   frame 3: Slim::Utils::Scan::readList (C:/Program Files/SlimServer6.5/server/Slim/Utils/Scan.pm line 219)
   frame 4: Slim::Utils::Scan::addToList_run (C:/Program Files/SlimServer6.5/server/Slim/Utils/Scan.pm line 159)
   frame 5: Slim::Utils::Scan::addToList (C:/Program Files/SlimServer6.5/server/Slim/Control/Commands.pm line 833)
   frame 6: Slim::Control::Commands::playlistXitemCommand (C:/Program Files/SlimServer6.5/server/Slim/Control/Request.pm
 line 1113)
   frame 7: (eval) (C:/Program Files/SlimServer6.5/server/Slim/Control/Request.pm line 1113)
   frame 8: Slim::Control::Request::execute (C:/Program Files/SlimServer6.5/server/Slim/Control/Request.pm line 580)
   frame 9: Slim::Control::Request::executeRequest (C:/Program Files/SlimServer6.5/server/Slim/Player/Client.pm line 101
1)
   frame 10: Slim::Player::Client::execute (C:/Program Files/SlimServer6.5/server/Plugins/LastFM/Plugin.pm line 976)
   frame 11: Plugins::LastFM::Plugin::playLastFM (C:/Program Files/SlimServer6.5/server/Plugins/LastFM/Plugin.pm line 51
2)
   frame 12: Plugins::LastFM::Plugin::action (C:/Program Files/SlimServer6.5/server/Plugins/LastFM/Plugin.pm line 441)
   frame 13: Plugins::LastFM::Plugin::__ANON__ (C:/Program Files/SlimServer6.5/server/Slim/Hardware/IR.pm line 694)
   frame 14: Slim::Hardware::IR::executeButton (C:/Program Files/SlimServer6.5/server/Slim/Control/Commands.pm line 113)

   frame 15: Slim::Control::Commands::buttonCommand (C:/Program Files/SlimServer6.5/server/Slim/Control/Request.pm line
1113)
   frame 16: (eval) (C:/Program Files/SlimServer6.5/server/Slim/Control/Request.pm line 1113)
   frame 17: Slim::Control::Request::execute (C:/Program Files/SlimServer6.5/server/Slim/Control/Request.pm line 580)
   frame 18: Slim::Control::Request::executeRequest (C:/Program Files/SlimServer6.5/server/Slim/Player/Client.pm line 10
11)
   frame 19: Slim::Player::Client::execute (C:/Program Files/SlimServer6.5/server/Slim/Hardware/IR.pm line 707)
   frame 20: Slim::Hardware::IR::processCode (C:/Program Files/SlimServer6.5/server/Slim/Hardware/IR.pm line 570)
   frame 21: Slim::Hardware::IR::releaseCode (C:/Program Files/SlimServer6.5/server/Slim/Hardware/IR.pm line 458)
   frame 22: Slim::Hardware::IR::checkRelease (C:/Program Files/SlimServer6.5/server/Slim/Utils/Timers.pm line 120)
   frame 23: Slim::Utils::Timers::checkTimers (slimserver.pl line 631)
   frame 24: main::idle (slimserver.pl line 562)
   frame 25: main::main (slimserver.pl line 1230)
Comment 6 James Craig 2006-01-25 23:51:47 UTC
after setting the timer, my plugin does the following, which I think is where the stack trace is showing up?

$client->execute(['playlist','play'],
 $players{$client->macaddress}->stream_url,
 $client->string('PLUGIN_LASTFM_MODULE_NAME')]
);
Comment 7 Adrian Smith 2006-01-26 10:46:52 UTC
The timer side of this actually looks correct.  Could you point me at the plugin and how to recreate it so I can see what it happening in more detail.
Comment 8 James Craig 2006-01-26 11:48:37 UTC
download the plugin from www.jamescraig.co.uk/SlimServer/LastFM116.zip and install. 
You'll need a www.Last.FM login (email me and I can send you mine) and enter this in internet radio settings.

Then enter the plugin via player's internet radio menu and press play.

Squeezebox will freeze (best to use Softsqueeze) and SlimServer hits 100% CPU. 
Does still respond to web requests though...
Comment 9 James Craig 2006-01-26 12:06:32 UTC
yes seems like the timers was a red herring! It's not behaving the same today.

Back to thinking the real problem is in the stream. If I try and open the LastFM stream url with the standard 'tune in' page, SlimServer freezes immediately after the 'opened stream' message from d_remotestream (as in original report).

I don't know what debug option might help after that?
Comment 10 Adrian Smith 2006-01-26 12:15:39 UTC
Right - the code path being executed here blocks the server while the content from the url is downloaded.  It does allow streaming to players and high priority timers while waiting for the content but nothing else.

Slimserver thinks the url is a playlist and is trying to download to the end of the page/file so it can then parse it.  Is the stream actually a playlist?

Debug --d_source, --d_parse may be useful
Comment 11 James Craig 2006-01-26 12:50:37 UTC
I don't think it's a playlist, just an mp3 stream. 
Using those debug options I don't get any extra info beyond what's in the original report. 
For comparison this is what I get running exactly the same code (and URL) on SS 6.2:

2006-01-26 20:47:27.5777 Opening connection to http://streamer1.audioscrobbler.com/last.mp3?Session=aa630ee5e2f407883909
6dad7c57b534: [streamer1.audioscrobbler.com on port 80 with path /last.mp3?Session=aa630ee5e2f4078839096dad7c57b534 with
 timeout 5]
2006-01-26 20:47:27.6132 Request: GET /last.mp3?Session=aa630ee5e2f4078839096dad7c57b534 HTTP/1.0
Accept: */*
Cache-Control: no-cache
User-Agent: iTunes/4.7.1 (Windows; N; Windows XP; 586; EN; cp1252) SlimServer/6.2.2/5520
Icy-MetaData: 1
Connection: close
Host: streamer1.audioscrobbler.com

2006-01-26 20:47:27.7449 Response: HTTP/1.0 200 OK
2006-01-26 20:47:27.7663 header: Server: last.fm Streaming Server
2006-01-26 20:47:27.7672 header: Content-type: audio/mpeg
2006-01-26 20:47:27.7855 header:
2006-01-26 20:47:27.7860 Recieved final blank line...
2006-01-26 20:47:27.7864 opened stream!
2006-01-26 20:47:27.7895 remoteURL is a song : http://streamer1.audioscrobbler.com/last.mp3?Session=aa630ee5e2f407883909
6dad7c57b534
2006-01-26 20:47:27.7932 Setting maxBitRate for Study to: 320
2006-01-26 20:47:27.7938 Setting maxBitRate for Study to: 320
2006-01-26 20:47:27.8008 undermax = 1, type = mp3, softsqueeze = 25:81:b0:4a:7c:0d, lame = C:\Program Files\SlimServer6.
2\server\Bin\lame.exe
2006-01-26 20:47:27.8087 checking formats for: mp3-flc-softsqueeze-25:81:b0:4a:7c:0d
2006-01-26 20:47:27.8093 checking formats for: mp3-flc-*-25:81:b0:4a:7c:0d
Comment 12 Adrian Smith 2006-01-26 13:28:00 UTC
The critical thing is does 6.5 show:
"remoteURL is a song"

If not then I think the problem is that 6.5 is treating the stream as a playlist rather than a song.  It therefore tries to download all of it and parse it...  Something which won't work for a continuous stream.

The remote streaming code is changed in 6.5 so this is possible.
Comment 13 Adrian Smith 2006-01-27 17:09:29 UTC
Not sure how Dan expects this to work, but I think the problem is that the params on the end of the url are not stripped off before calling typeFromSuffix in typeFromPath.  This means your url is not recognised as a song and hence is processes as if it were a playlist url.

Dan - where should this functionality go

The following is a possible patch:
[slimserver@vig ~]$ diff -du trunk/server/Slim/Music/Info.pm Slim/Music/Info.pm
--- trunk/server/Slim/Music/Info.pm     2006-01-27 18:19:38.000000000 +0000
+++ Slim/Music/Info.pm  2006-01-28 01:06:07.000000000 +0000
@@ -1072,8 +1072,14 @@
 
                        $anchorlessPath = Slim::Utils::Misc::stripAnchorFromURL($fullpath);
 
+                       if ($anchorlessPath =~ /(.*)\?(.)/) {
+                               $anchorlessPath = $1;
+                       }
+
                        $type = typeFromSuffix($anchorlessPath, $defaultType);
+
                }
+
        }
 
        # We didn't get a type from above - try a little harder.
Comment 14 Dan Sully 2006-01-27 17:21:54 UTC
Seems reasonable to me. Check to make sure it's a remote URL maybe?
Comment 15 Adrian Smith 2006-01-27 17:40:11 UTC
James - could you try svn 5895?
Comment 16 James Craig 2006-01-28 01:24:46 UTC
Working now! Thanks very much!