Bugzilla – Bug 9003
Occasional loud noises when moving to a new Rhapsody track
Last modified: 2009-09-08 09:27:44 UTC
Created attachment 3737 [details] please see at 18:52:10 Occasionally when SB3 moves on to a new Rhapsody track, it emits a series of intermittent loud scratch & pop noises While it happens, the display alternates rapidly between various states. The situation usually resolves itself after a few minutes. The problem is random and happens every few hours of normal play. It is a new phenomena that has started in SN and SC after 7.1 upgrade Firmware version is latest that was released with version 7.1 The logs are from SqueezeCenter Version: 7.1 - 22170 @ Mon Jul 28 13:36:57 PDT 2008 In attached log the problem has started at 18:52:10 and was resolved on its own at 18:54:28 One thing to notice in the logs is that a normal track switch printed [08-08-02 18:51:59.6771] Slim::Player::Source::decoderUnderrun (607) 00:04:20:12:1a:99: Decoder underrun while this mode: playout-play while the abnormal track switch printed [08-08-02 18:52:10.0302] Slim::Player::Source::outputUnderrun (800) 00:04:20:12:1a:99: Output buffer underrun (decoder: 88209 / output: 0)
QA to reproduce.
The buffer underrun looks like a network issue. We'll have a look.
Please note however that in all the series of output buffer underrun events that occur every few seconds between 18:52:10 and 18:54:28, the decoder buffer has some data in it. To me this does not suggest an external network to decoder buffer issue, but a problem in decoder->output as if no raw PCM audio can be properly produced from the decoder data. Couple this with the fact that the format has changed to 192kbps MP3 newly encoded by Rhapsody, perhaps not perfectly.
Forum discussion related to this bug takes place at http://forums.slimdevices.com/showthread.php?t=50509
There are 2 issues here: 1. Some Rhapsody tracks are badly corrupted, for example "The Way You Look Tonight" on album "Blue And Sentimental" by artist "Arnett Cobb". The situation on this track is improved by a patch in bug 9046. I've also asked Rhapsody to look into why some tracks are corrupt like this. 2. Rare glitches during track transitions. I haven't been able to reproduce it yet.
Is this a side effect of moving to MP3?
You could say that. Who knew they'd have corrupt tracks?
I left an SB3 playing the top tracks of artist Ron Sexsmith from 10am till 8pm and encountered 3 incidents of track transition glitches around 1pm, 2pm, 5:30pm You may want to try this if attempting to reproduce: Rhapsody / My Library / Artists / Ron Sexsmith / More from Ron Sexsmith... / Top Tracks If you'd like me to provide logs with different debug options than the one already attached, please let me know
Thanks, I've been letting it play various things all day hoping to catch a case of this. Unfortunately there is no debug setting that you can set to get more info than player.source. The problem is in the firmware.
I believe now this bug is not so much a track transition glitch, but rather a full track that's being "played" with pops from start to finish. My reasoning is in the forum thread.
I have noticed the scratchy noises when Tracks are changing via Rhapsody. Strange thing is that I cannot seem to repeatedly reproduce this issue. It happens very very randomly.
New firmware due out in the next day or so should hopefully fix this bug. My current theory is that this is the same thing you were seeing with WMA in bug 7492, but due to a bug in our error handling the MP3 decoder wasn't giving up properly when it ran into an error decrypting the Rhapsody data. The new firmware also includes some extra debugging codes sent to the server to help track down exactly what's failing when this happens.
(In reply to comment #12) I have the same problem and have communicated it to Anoop. Fred Rothenberg
Please test new firmware in 7.2. Watch your logs for this line: "Rhapsody decoding failure: code xxx" If you see this, let me know.
Created attachment 3765 [details] please see at 17:56:43
Reproduced with with Ron Sexsmith playlist on song #37 which played fully with pops, then continued normally to song #38 This is with firmware version 110 under SqueezeCenter Version: 7.2 - 22491 @ Sat Aug 9 02:02:58 PDT 2008 - Windows XP Log is similar to 7.1 logs, I see no "Rhapsody decoding failure: code xxx" message
I had the following log settings at DEBUG: plugin.rhapsodydirect, player.source, player.streaming.direct Please let me know if anything else had to be under debug
Argh, did it sound the same as before?
Andy: Is it possible to make the mp3/wma choice a server-controllable option? I'm worrying that we should be able to roll back as we get closer to release.
I'm going to send y360 a debug firmware to see if he can get some more details on the problem, since he's the only one who can reliably reproduce it.
Maybe it was more scratch then pop this time round Hard to tell because I typically scoot to my preamp and lower the volume to prevent damage to my hifi when it happens. I'll try to notice if it happens again. I did notice that the logs are slightly different this time round - the decode buffer seems to be almost empty when the output buffer underrun message is printed - i.e. classic output buffer underrun as in pre-7.1 versions caused by nearly empty decode buffer. This was not the case in 7.1 logs.
(In reply to comment #21) I just tried to listen to Horowitz-Rachmaninoff-Concerto 3 under Rhapsody-Classical-Staff Picks. Could not get anything but intermittent scratchy static. Would not even start playing. Clicked on Summa by Arvo in the same playlist and the music started right up. Fred
Sorry, forgot to mention that I'm still on 7.1 Fred (In reply to comment #22) > (In reply to comment #21) > I just tried to listen to Horowitz-Rachmaninoff-Concerto 3 under > Rhapsody-Classical-Staff Picks. > Could not get anything but intermittent scratchy static. Would not even start > playing. > Clicked on Summa by Arvo in the same playlist and the music started right up. > Fred
Please upgrade to 7.2 with the latest firmware.
Are you asking me to be a "beta" tester? I note that the download site says this version may be unstable. Fred (In reply to comment #24) > Please upgrade to 7.2 with the latest firmware.
Yes, if you are interested in this bug. 7.2 is not unstable.
OK, I'm running the debug firmware now with the proper debug options and can see the trace messages in the log. I'll let you know when an incident occurs.
(In reply to comment #16) > Reproduced with with Ron Sexsmith playlist on song #37 which played fully with > pops, then continued normally to song #38 > > This is with firmware version 110 under > SqueezeCenter Version: 7.2 - 22491 @ Sat Aug 9 02:02:58 PDT 2008 - Windows XP > > Log is similar to 7.1 logs, I see no "Rhapsody decoding failure: code xxx" > message > Andy, I don't have any news yet from debug firmware run. However I inspected the logs of 7.2 which had a glitch on #37, and noticed this on track #59: Rhapsody decoding failure: code 101 Looks like the track got skipped. I will attach the log shortly.
Created attachment 3766 [details] Rhapsody decoding failure: code 101 at track #59
OK, great, that is probably the same skip bug we've seen before. Code 101 means the firmware thinks the .rad file is invalid.
Debug firmware version status: I have not reproduced any noise or output buffer underrun as of yet, but that may be because the player stops/hangs unpredictably every few hours in the middle of tracks, with the audio suddenly cutting off. There are two variations to this problem: - In some cases the display remains frozen at xx (e.g. 22) seconds into the track, and a jump command from remote proceeds normally to next track. - In other cases the display suddenly goes dark and does not respond to remote, and I have to power cycle. I do have the relevant logs for each case if they're of any interest. I've tried on a different player to rule out any hardware issue and results are same. I have not seen anything like this prior the the debug firmware.
OK, you may be able to improve the situation by running the player with ethernet instead of wireless, it will use less memory that way.
Created attachment 3769 [details] Player freeze The freezeups happen after playing just a couple of tracks sometimes In attached log encountered silence, player froze, I power-cycled at 07:10:20, but please see decoding errors prior to that Is this really memory related ?
The above case is freeze-up on track #6 where track #1 was after power cycling
Created attachment 3770 [details] player freeze 2 In this case it played 2 tracks after power cycle before freezing up on track switch to number 3 I'll go to wired if you really think it would make a difference
Yeah I'm more interested in reproducing the noise rather than crashes that only occur in debug mode. If the crashes continue in wired mode I'll look into it some more.
I see this in the log... I was not around to listen but it does not have the output buffer underrun messages. [08-08-10 09:37:07.6745] Slim::Networking::Slimproto::_debug_handler (563) [00:04:20:12:11:11] 01621.728: Error: radeadecoder.c[249]: not a version 3 EA file [08-08-10 09:37:07.6756] Slim::Networking::Slimproto::_debug_handler (563) [00:04:20:12:11:11] 01621.730: Trace: radeadecoder.c[97]: sending error status 105 [08-08-10 09:37:07.6765] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (145) 00:04:20:12:11:11 Got RPDS packet: \"i" [08-08-10 09:37:07.6771] Slim::Plugin::RhapsodyDirect::RPDS::rpds_handler (153) Rhapsody decoding failure: code 105
I assume that track was just skipped? So far you have run into "not a version 3 RAD file" and "not a version 3 EA file". Very interesting.
Created attachment 3772 [details] player hangs when track is not available in 192kbps mp3 Player hangs when a track is not available in 192kbps mp3 "Reached end of EA" is dumped indefinitely This can be reproduced by playing Rhapsody top tracks of Billy Joe Shaver on transition from track #3 to track #4 No luck on the noise yet
Unexplained crashes gone once I left only one player with debug firmware connected. No error and nothing out of the ordinary in logs under debug firmware after playing consecutive 12 hours in wireless, then 12 consecutive hours in wired. Will keep trying.
adding James to the cc list since he's seen this bug :)
I've installed 7.2-22491 and haven't had any problems with any of the albums that had given me trouble last week, or with the Billy Joe Shaver or Horowitz:Rachmaninoff tracks.
I have not been able to reproduce the noise with the debug firmware nor with the normal 110 firmware, so perhaps the incident in comment #15 was a fluke. There are several more documented code 101, as well as more code 105 with "not a version 3 EA file". These all result in track skips. There are also more documented cases of "No EA Found. Invalid Combination of Track Id..." which result in player stopping. These seem random, i.e. the same track will play fine later on But no noise, so maybe this bug can be closed for now - per your discretion
OK that's good, we still need to track down the cause of code 101 and 105, but if that happens it should just skip to the next track.
Created attachment 3801 [details] Thar she blows I was not around to listen but I'm pretty sure this is the real McCoy See to 08-08-13 09:15:26 to 08-08-13 09:16:39
Great, that does indeed look like the bug.
Hopefully fixed in firmware 111. I am going to open new bugs for the other Rhapsody issues that cause skipped tracks.
Created attachment 3812 [details] firmware 111 - see at 09:22:22 Upgraded to firmware 111 SqueezeCenter Version: 7.2 - 22618 @ Fri Aug 15 02:03:05 PDT 2008 - Windows XP - EN Tracks still randomly mis-play, but it sounds different now. Instead of a series of pops, it is now mostly silent except for what can be described a sudden scratch noise every few seconds. The noise corresponds to the "rebuffering" message on the display.
Created attachment 3816 [details] rhapsody underrun
I upgraded to 111. I'm still getting some errors, though the popping/screeching lasts for only a few seconds, then the sb3 advances to the next track.
I heard a few errors today as well, skips to the next track about 1-2 sec after the noise. I use SN not SC
James notes this happened over the weekend on a Rhapsody Channel, if that makes a difference.
I also experienced this over the last weekend at home, streaming from my Rhapsody Library. Our Internet connection was very poor over the weekend.
Please try firmware 112. I think I've fixed the bug that caused code 105, but there are still a couple of other bugs left. y360: I'll send you another debug firmware so you can get some more data.
Created attachment 3840 [details] firmware 112 - noise I was not around to listen, I believe this is the noise
OK, that looks like the same log Ross got, but he described it as a short glitch followed by some amount of silence before going to the next track. Your log is truncated a bit, what track was playing right before the failed track?
Created attachment 3843 [details] firmware 112 - noise - see 03:38:13 Here's a fuller log. When this happens the track plays silently for a couple of minutes with bursts of noise when the rebuffering comes on. I did not observe immediate skips. My experience matches what's in the log.
Maybe a faster connection would result in less pause/resume events within the track, i.e. maybe it would have fewer rebuffering events within the track, which might explain the difference with what Ross experienced. The noise is periodic within the track. It corresponds to the pause/resume/rebuffer cycle.
How fast is your connection? They have 100mb at the office so I expect they won't have any problem keeping the buffer full and won't hear the same glitches. Please also try the new firmware I sent.
I have 2.5mb I do not believe a faster connection type will avoid the noise, but it might result in fewer bursts of noise and a faster skip. See for example the log from Jon Bernard. The decoding still goes wrong, but the rebuffering that takes place as result is very fast, e.g. 2707885 / 120000 compared what I have in my log. This seems to result in a cycle of pause/rebuffer/resume/pause/rebuffer/resume that takes place from 13:29:26 till 13:29:51 and corresponds to two noise outbursts. My connection is probably slower, so I see typically a cycle of 5 pause/rebuffer/resume which corresponds to 5 noise outbursts and takes place over a longer period. The only thing that can be said is that a faster internet connection would result in fewer noise outbursts over a shorter period of silence. A slower connection would experience a longer cycle silence/noise/silence/noise/... within the track Anyway I do not think you put the blame on connection problems, because as you can see my log is perfect network-wise before and after the problem track. There is definitely a decoding problem here. It just manifests itself differently. This is from the attached log of Jon Bernard: [08-08-16 13:29:26.0580] Slim::Player::Source::trackStartEvent (1649) Song queue is now 2 [08-08-16 13:29:26.4299] Slim::Player::Source::outputUnderrun (800) 00:04:20:06:be:04: Output buffer underrun (decoder: 2560457 / output: 0) [08-08-16 13:29:26.4632] Slim::Player::Source::playmode (309) 00:04:20:06:be:04: Switching to mode pause from playout-play [08-08-16 13:29:26.4644] Slim::Player::Source::playmode (412) 00:04:20:06:be:04 New play mode: pause [08-08-16 13:29:26.5115] Slim::Player::Source::playmode (581) 00:04:20:06:be:04: Current playmode: pause [08-08-16 13:29:27.5538] Slim::Player::Source::rebuffer (900) Rebuffering: 2707885 / 120000 [08-08-16 13:29:27.5542] Slim::Player::Source::playmode (309) 00:04:20:06:be:04: Switching to mode play from pause [08-08-16 13:29:27.5557] Slim::Player::Source::playmode (412) 00:04:20:06:be:04 New play mode: resume [08-08-16 13:29:27.5570] Slim::Player::Source::playmode (430) 00:04:20:06:be:04: Resume, resetting mode: playout-play [08-08-16 13:29:27.5601] Slim::Player::Source::playmode (581) 00:04:20:06:be:04: Current playmode: resume [08-08-16 13:29:35.8310] Slim::Player::Source::outputUnderrun (800) 00:04:20:06:be:04: Output buffer underrun (decoder: 3142673 / output: 0) [08-08-16 13:29:35.8314] Slim::Player::Source::playmode (309) 00:04:20:06:be:04: Switching to mode pause from playout-play [08-08-16 13:29:35.8326] Slim::Player::Source::playmode (412) 00:04:20:06:be:04 New play mode: pause [08-08-16 13:29:35.8340] Slim::Player::Source::playmode (581) 00:04:20:06:be:04: Current playmode: pause [08-08-16 13:29:36.8451] Slim::Player::Source::rebuffer (900) Rebuffering: 3142765 / 120000 [08-08-16 13:29:36.8456] Slim::Player::Source::playmode (309) 00:04:20:06:be:04: Switching to mode play from pause [08-08-16 13:29:36.8466] Slim::Player::Source::playmode (412) 00:04:20:06:be:04 New play mode: resume [08-08-16 13:29:36.8478] Slim::Player::Source::playmode (430) 00:04:20:06:be:04: Resume, resetting mode: playout-play [08-08-16 13:29:36.8494] Slim::Player::Source::playmode (581) 00:04:20:06:be:04: Current playmode: resume [08-08-16 13:29:51.7195] Slim::Player::Source::decoderUnderrun (607) 00:04:20:06:be:04: Decoder underrun while this mode: playout-play [08-08-16 13:29:51.7200] Slim::Player::Source::nextsong (1700) The next song is number 3, was 2
Oh, I know, there is definitely a bug, it just may be worse if you have a slower connection.
(In reply to comment #60) > I have 2.5mb > I do not believe a faster connection type will avoid the noise, but it might > result in fewer bursts of noise and a faster skip. > My connection is probably slower, so I see typically a cycle of 5 > pause/rebuffer/resume which corresponds to 5 noise outbursts and takes place > over a longer period. You're correct, I have a 6Mb connection, which was otherwise not in use at the time.
Andy, I heard the same short scratch-like noise when this MP3 radio station was rebuferring. http://www.shoutcast.com/sbin/tunein-station.pls?id=653847&filename=playlist.pls This suggests that there are two separate issues: - decoding problems on random Rhapsody tracks which are silent but trigger rebuffering - short scratch-like noise when an mp3 stream is rebuffering I think you will reproduce the noise if you manage to force rebuffering into the decoding of any valid MP3 stream. Perhaps you can find some way to limit your bandwidth.
Created attachment 3849 [details] glitches remain with 112 Same glitches with 112. The log begins from the point when I loaded a new album to when things calmed down.
y360: Yeah you're right, rebuffering does introduce a small glitch due to the delay between the player's output underrun message and the server's pause command. I think making the player auto-pause in this case would avoid the glitches.
Haven't heard about this for a while. Please add your comments as we continue to monitor this bug.
I'm still having problems. Note that my connection is now 1.5Mb, down from 6Mb. I'm attaching my latest log.
Created attachment 4183 [details] more glitches
Could you please try 7.3?
Still happens in 7.2.1 Will try 7.3
Created attachment 4184 [details] glitches with fw 116 Upgraded to 7.3 and firmware 116; and got some pops after a of couple hours. Let me know if you'd like me to turn on different logging settings.
Created attachment 4192 [details] glitches with fw 117 A few seconds of noise at the beginning of the track, silence, then the next track began. I think that's always the pattern now -- ie, there's never noise in the middle of a track.
Can you please try the latest firmware, 118? I fixed a bug that could cause this situation when skipping tracks or seeking.
Created attachment 4213 [details] 118 In a few hours of listening I haven't heard any popping. However, whenever a track has to be rebuffered, there's silence, and this happens seemingly constantly, and in exactly the same places every time. This is a new problem. This doesn't occur when I play this album through the Rhapsody application, though, or through the web at work.
Hmm, did that track continue playing OK after it rebuffered? You said it rebuffers in the same place every time on that track?
(In reply to comment #75) > Hmm, did that track continue playing OK after it rebuffered? You said it > rebuffers in the same place every time on that track? > Not just this track; it happens in several places on every track (on this album, I didn't try any others), and yes, always the same places. The tracks all seem to continue playing OK after the rebuffering.
Created attachment 4221 [details] more from 118 I've got my 6Mb connection back, and the problem I was having previously (frequent, repeatable long sileneces) hasn't recurred. But the infrequent, unpredictable pops have returned.
Tried a bit to track this bug down tonight. One way that I've been able to reproduce it tonight has been to soft-reboot (hold power) the player and play a Rhapsody track after it boots back up. Maybe 10% of the time this results in the bug. I am pretty sure that once a track plays normally, the bug will not appear again until the player has not been playing for a while. I am always hit by this when starting Rhapsody in the morning or after a reboot, never while just listening to a lot of tracks in a row.
(In reply to comment #78) > I am pretty sure that once a track plays normally, the bug will not appear > again until the player has not been playing for a while. I am always hit by > this when starting Rhapsody in the morning or after a reboot, never while just > listening to a lot of tracks in a row. This hasn't been true for me, at least prior to 119. Since upgrading to 119 I haven't had a problem in about 6 hours of listening, however.
*** Bug 8836 has been marked as a duplicate of this bug. ***
Created attachment 4308 [details] 119 Still having intermittent problems with 119.
I mentioned symptoms that sound like this problem in the thread below: http://forums.slimdevices.com/showthread.php?t=54780&highlight=rhapsody&page=3 I switched to version 7.3, and am still seeing the problem. An example is I played Amy Winehouse Back to Black yesterday and two of the songs off the album exhibited the symptom of silence and some low level pops and then it skipped to the next track. This happened again this morning, but on different songs. One thing I tried this morning was manually skipping back to the song that showed the problem, and it then played OK. Is anyone else still reporting this problem? I'm using version 7.3 r3437.
Created attachment 4377 [details] 120 Still having problems. (Am I the only one?)
Just to confirm still happens with firmware 120
It's also happening with SBR version 55... it seems like more frequently on SN vs SC.
This bug should be fixed in the next firmware, it is undergoing testing now.
New firmware is in tonight's 7.3.1 nightly. Unfortunately Rhapsody is having a lot of problems which will probably make it hard to verify this bug has been fixed.
SqueezeCenter 7.3.1 r24367 Controller 7.3 r3476 Receiver r56 SB2/3 r121 Transporter r71 Boom r41
(In reply to comment #88) Would everyone having this issue please test the above versions, then report back if this has solved the issues for them. Thanks.
(In reply to comment #89) > (In reply to comment #88) > > Would everyone having this issue please test the above versions, then report > back if this has solved the issues for them. Thanks. > Running Version: 7.3.1 - 24367 @ Thu Dec 18 10:00:25 PST 2008 No clicks or pops anymore but still some glitches (play halts) and associated log messages: [08-12-19 10:02:07.6521] Slim::Plugin::RhapsodyDirect::Plugin::rpds_handler (320) 00:04:20:07:d9:cd Rhapsody decoding failure: code 110 [08-12-19 10:50:43.5621] Slim::Plugin::RhapsodyDirect::Plugin::rpds_handler (320) 00:04:20:07:d9:cd Rhapsody decoding failure: code 110 [08-12-19 10:50:52.1665] Slim::Plugin::RhapsodyDirect::Plugin::rpds_handler (320) 00:04:20:07:d9:cd Rhapsody decoding failure: code 110 Best regards, Charles Razzell.
OK, code 110 is because Rhapsody is still having playback problems. Not related to this bug.
I haven't heard it yet on receiver r56...
This bug has been fixed in the 7.3.1 release version of SqueezeCenter! Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already. If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.