Bugzilla – Bug 4202
KCRW stalls on SLIMP3 but not Squeezebox
Last modified: 2006-10-04 08:08:13 UTC
I recently upgraded from server v6.3.1 to v6.5 and just about everything is running very smoothly. However, I'm having problems playing Internet radio (specifically KCRW World News in Slim Devices Picks) on our two SLIMP3s. We listen to KCRW every morning and it tends to stall and stop after a few minutes of playback on the SLIMP3. We have the same behavior on our other SLIMP3 but I have successfully played KCRW on our Squeezebox for several hours - so I think this is a SLIMP3-specific issue. I'll try to capture some debugging flags and add them to this bug report.
d_stream reports lots of these up until when the stream stops. Unfortunately I didn't have logging turned on at the moment the stream stopped. 2006-09-23 16:19:34.5882 00:04:20:04:14:90 1159053574.58816 Timeout on seq: 53045 2006-09-23 16:19:34.6482 00:04:20:04:14:90 1159053574.64817 Timeout on seq: 53045 2006-09-23 16:19:34.7084 00:04:20:04:14:90 1159053574.70841 Timeout on seq: 53045 2006-09-23 16:19:34.7683 00:04:20:04:14:90 1159053574.76824 Timeout on seq: 53045 2006-09-23 16:19:34.8284 00:04:20:04:14:90 1159053574.82836 Timeout on seq: 53045 2006-09-23 16:19:34.8882 00:04:20:04:14:90 1159053574.88816 Timeout on seq: 53045 2006-09-23 16:19:34.9483 00:04:20:04:14:90 1159053574.9483 Timeout on seq: 53045 2006-09-23 16:19:35.0203 00:04:20:04:14:90 1159053575.02025 Timeout on seq: 53045 2006-09-23 16:19:35.0782 00:04:20:04:14:90 1159053575.07814 Timeout on seq: 53045 2006-09-23 16:19:35.1388 00:04:20:04:14:90 1159053575.13872 Timeout on seq: 53045 2006-09-23 16:19:35.1984 00:04:20:04:14:90 1159053575.1984 Timeout on seq: 53045 2006-09-23 16:19:35.2583 00:04:20:04:14:90 1159053575.25831 Timeout on seq: 53045 2006-09-23 16:19:35.3217 00:04:20:04:14:90 1159053575.32164 Timeout on seq: 53045 2006-09-23 16:19:35.3781 00:04:20:04:14:90 1159053575.37812 Timeout on seq: 53045 2006-09-23 16:19:35.4382 00:04:20:04:14:90 1159053575.43813 Timeout on seq: 53045 2006-09-23 16:19:35.4981 00:04:20:04:14:90 1159053575.4981 Timeout on seq: 53045 2006-09-23 16:19:35.5582 00:04:20:04:14:90 1159053575.55814 Timeout on seq: 53045 2006-09-23 16:19:35.6181 00:04:20:04:14:90 1159053575.6181 Timeout on seq: 53045 2006-09-23 16:19:35.6781 00:04:20:04:14:90 1159053575.67812 Timeout on seq: 53045 2006-09-23 16:19:35.7381 00:04:20:04:14:90 1159053575.7381 Timeout on seq: 53045 2006-09-23 16:19:35.7982 00:04:20:04:14:90 1159053575.79812 Timeout on seq: 53045 2006-09-23 16:19:35.8582 00:04:20:04:14:90 1159053575.85816 Timeout on seq: 53045 2006-09-23 16:19:35.9181 00:04:20:04:14:90 1159053575.91811 Timeout on seq: 53045 2006-09-23 16:19:35.9782 00:04:20:04:14:90 1159053575.97817 Timeout on seq: 53045 2006-09-23 16:19:36.0383 00:04:20:04:14:90 1159053576.03828 Timeout on seq: 53045 2006-09-23 16:19:36.0981 00:04:20:04:14:90 1159053576.09806 Timeout on seq: 53045 2006-09-23 16:19:36.1584 00:04:20:04:14:90 1159053576.15834 Timeout on seq: 53045 2006-09-23 16:19:36.2182 00:04:20:04:14:90 1159053576.21816 Timeout on seq: 53045 2006-09-23 16:19:36.2782 00:04:20:04:14:90 1159053576.27815 Timeout on seq: 53045 2006-09-23 16:19:36.3381 00:04:20:04:14:90 1159053576.33806 Timeout on seq: 53045 2006-09-23 16:19:36.3982 00:04:20:04:14:90 1159053576.39815 Timeout on seq: 53045 2006-09-23 16:19:42.0795 00:04:20:04:14:90 1159053582.07943 Timeout on seq: 53216 2006-09-23 16:19:42.1377 00:04:20:04:14:90 1159053582.1377 Timeout on seq: 53216 2006-09-23 16:19:42.1980 00:04:20:04:14:90 1159053582.19795 Timeout on seq: 53216 2006-09-23 16:19:42.2580 00:04:20:04:14:90 1159053582.25799 Timeout on seq: 53216 2006-09-23 16:19:42.3178 00:04:20:04:14:90 1159053582.3178 Timeout on seq: 53216 2006-09-23 16:19:42.3811 00:04:20:04:14:90 1159053582.3811 Timeout on seq: 53216 2006-09-23 16:20:36.4240 00:04:20:04:14:90 1159053636.424 Timeout on seq: 54372 2006-09-23 16:20:41.4937 00:04:20:04:14:90 1159053641.49366 Timeout on seq: 54478 2006-09-23 16:20:41.5536 00:04:20:04:14:90 1159053641.55362 Timeout on seq: 54478
appaerntly kcrw required a recent change to a new stream. could it be a buffering problem with the new connection to their server?
Ross, could you try to reproduce? Come get a SliMP3 from my cube if you need one.
Bug 4250 is blocking a precise reproduction at the moment, but using my brain for an XML parser I can see the url from the picks .opml file: http://www.kcrw.org/pls/kcrwworldnews.pls As the user reports, it works with SB2/3 (which reports it is a 64kbps mp3 stream) but doesn't seem to play on SliMP3. Perhaps Andy can look at the stream in more detail or something? I've reduced the severity primarily to prevent this bug from interfering with the 6.5.1 launch, which it has little to do with.
Yeah I have been meaning to look into this.
So I hooked up my SLIMP3, and in the web interface went to Picks -> Best of -> and clicked play on KCRW Worldnews. After a brief wait while SlimServer scanned the playlist, it started playing and has been playing for 2 minutes with no problems. Debug log (--d_stream --d_remotestream --d_scan --d_parse) looks like: 2006-09-29 13:41:49.3396 scanRemoteURL: opening remote location http://www.kcrw.org/pls/kcrwworldnews.pls 2006-09-29 13:41:51.2751 scanRemoteURL: Content-Type is pls for http://www.kcrw.com/pls/kcrwworldnews.pls 2006-09-29 13:41:51.2806 scanRemoteURL: found that http://www.kcrw.com/pls/kcrwworldnews.pls is a playlist 2006-09-29 13:41:51.2857 parseList (type: pls): http://www.kcrw.com/pls/kcrwworldnews.pls 2006-09-29 13:41:51.3051 Parsing playlist: http://www.kcrw.com/pls/kcrwworldnews.pls 2006-09-29 13:41:51.3058 Parsing line: [playlist] numberofentries=4 File1=http://scfire-chi0l-2.stream.aol.com:80/stream/1047 Title1=(#1 - 2/500) KCRW Worldnews Length1=-1 File2=http://scfire-ntc0l-1.stream.aol.com:80/stream/1047 Title2=(#2 - 4/500) KCRW Worldnews Length2=-1 File3=http://scfire-ntc0l-2.stream.aol.com:80/stream/1047 Title3=(#3 - 4/500) KCRW Worldnews Length3=-1 File4=http://scfire-chi0l-1.stream.aol.com:80/stream/1047 Title4=(#4 - 19/500) KCRW Worldnews Length4=-1 Version=2 2006-09-29 13:41:51.3534 scanPlaylistFileHandle: found 1 items in playlist: 2006-09-29 13:41:51.3535 http://scfire-chi0l-2.stream.aol.com/stream/1047 2006-09-29 13:41:51.3668 scanRemoteURL: opening remote location http://scfire-chi0l-2.stream.aol.com/stream/1047 2006-09-29 13:41:51.5748 scanRemoteURL: Content-Type is mp3 for http://scfire-chi0l-2.stream.aol.com/stream/1047 2006-09-29 13:41:51.5802 scanRemoteURL: found that http://scfire-chi0l-2.stream.aol.com/stream/1047 is audio [mp3] 2006-09-29 13:41:51.5873 scanRemoteURL: Found bitrate in header: 64000 2006-09-29 13:41:51.5948 scanPlaylistURLs: Found an audio URL: http://scfire-chi0l-2.stream.aol.com/stream/1047 [mp3] 2006-09-29 13:41:51.5992 Opening connection to http://scfire-chi0l-2.stream.aol.com/stream/1047: [scfire-chi0l-2.stream.aol.com on port 80 with path /stream/1047 with timeout 10] 2006-09-29 13:41:51.6294 Request: GET /stream/1047 HTTP/1.0 Accept: */* Cache-Control: no-cache User-Agent: iTunes/4.7.1 (Macintosh; N; Mac OS X 10.4.7 (8J2135); ppc-darwin; EN; utf8) SlimServer/6.5.1/TRUNK Icy-MetaData: 1 Connection: close Host: scfire-chi0l-2.stream.aol.com 2006-09-29 13:41:51.6735 Response: ICY 200 OK 2006-09-29 13:41:51.6761 header-rs: icy-notice1: <BR>This stream requires <a href="http://www.winamp.com/">Winamp</a><BR> 2006-09-29 13:41:51.6764 header-rs: icy-notice2: Firehose Ultravox/SHOUTcast Relay Server/Linux v2.3.0<BR> 2006-09-29 13:41:51.6766 header-rs: icy-name: KCRW Worldnews 2006-09-29 13:41:51.6771 header-rs: icy-genre: News 2006-09-29 13:41:51.6772 header-rs: icy-url: http://www.kcrwworldnews.com 2006-09-29 13:41:51.6773 header-rs: content-type: audio/mpeg 2006-09-29 13:41:51.6896 header-rs: icy-pub: 1 2006-09-29 13:41:51.6900 header-rs: icy-metaint: 24576 2006-09-29 13:41:51.6901 header-rs: icy-br: 64 2006-09-29 13:41:51.6949 parseHeaders: Bitrate for http://scfire-chi0l-2.stream.aol.com/stream/1047 set to 64000 2006-09-29 13:41:51.6994 opened stream! 2006-09-29 13:41:51.7588 00:04:20:02:00:ec new stream 2006-09-29 13:41:51.8653 stream not readable 2006-09-29 13:41:51.9468 stream not readable 2006-09-29 13:41:52.0117 metadata: StreamTitle='';StreamUrl=''; 2006-09-29 13:41:52.1789 stream not readable 2006-09-29 13:41:52.2299 stream not readable 2006-09-29 13:41:52.3346 00:04:20:02:00:ec Buffer full, starting playback 2006-09-29 13:41:52.4038 stream not readable 2006-09-29 13:41:52.4545 stream not readable 2006-09-29 13:41:52.8321 stream not readable 2006-09-29 13:41:52.9126 stream not readable 2006-09-29 13:41:52.9634 stream not readable 2006-09-29 13:42:11.0344 00:04:20:02:00:ec 1159551731.03441 Timeout on seq: 538 2006-09-29 13:42:40.6090 00:04:20:02:00:ec 1159551760.609 Timeout on seq: 1253
Created attachment 1608 [details] logfile Here's a sample log from my slimserver with the same debug flags, showing the stream stopping after a short time.
The SLIMP3 code will auto-stop if it doesn't get an ACK packet in 30 seconds, and it waits 0.05 seconds for each ACK packet before retrying. This is what all those timeout messages are about. Are you sure you don't have network or internet problems? Can you play KCRW on both SLIMP3 and SB at the same time, and the SB will be fine?
Also, do other radio stations or local content (try 320k mp3 for the most network load) work fine? If you've got network problems I'd expect it to fail on everything.
I started KCRW on the SLIMP3 and the Squeezebox at the same time. The SLIMP3 stopped after about 2 1/2 minutes while the Squeezebox continued. Then I tried playing a few more stations on the SLIMP3. I tried Virgin FM Pop, HizRadio Pop, and radioIO80s Pop. I let all of these play for at least 5 minutes without problems. At the end of the test KCRW was still playing on the Squeezebox. We're on a pretty stable cable modem connection - I wouldn't suspect network congestion. It does seem to be limited to KCRW. Do you know of any high-bitrate streams I could test - or else a stream with the same characteristics of KCRW?
I upgraded to SlimServer Version: 6.5.1 - 10145 - Debian - EN - iso-8859-1 and KCRW is playing again normally. I'll close out this again and re-open if the problem recurs.