Bugzilla – Bug 6508
Occasional songs freeze with no sound
Last modified: 2009-09-08 09:27:16 UTC
This has been happening for several builds now. In the middle of a playlist a song will "play" with no sound. This means that it shows as playing, the elapsed/remaining time count, artwork changes, etc. but no sound is audible. Clicking on the "go back" then the "go forward" icons causes the song to restart and play normally. Different songs, different playlists, only after it has been playing for a while so probably only on a playlist page other than the first. FYI: 2 SBs synced, but I've only happened to notice this when 1 of them is in "off" mode, I don't remember this occurring prior to having 2 SBs - might be related.
Alan: This sounds like a sync issue. What additional information do you need?
I have noticed something similar when I yank the power from a synced SliMP3. I had though it was just because one could not tell that the SliMP3 was disconnected, but there is clearly an issue with disconnected or 'off' members of a sync-group. I'll look at it. Doug, if you can reproduce it reasonably easily, then a log with levels player.source=debug and player.sync=debug, along with a commentary of what happened, would be useful.
Here is the log file (partial) with the debugs turned on. It played Hinder, then froze up playing Kelly Clarkson. After a short bit when it wasn't doing anything I hit the back button on the web interface and it started Hinder again. I then hit the forward button on the web interface and it played the Kelly Clarkson song correctly. Note: This is slightly different than what I originally stated. It did not appear to be progressing through the Kelly Clarkson song. However, the play/pause icon on the web interface was "pause" indicating that I could pause it and that it was playing. The difference is potentially due to a different song that has about 1 minute of silence at the end - leading to me thinking that they played on in silence. Sorry for the erroronous info.
Created attachment 2599 [details] Log file
More info about system: Wired network. Windows XP, sp2 server doing essentially nothing but serving squeezecenter (anti-virus, etc.) SB3 "Main" was playing. SB3 "Bedroom" was powered and connected to the network but not in "on" mode. It's configuration is to be sync'd to the main SB3. Web interface client is Windows Vista, wasn't connected to server until after freeze ocurred. Happens on different songs. Very sporatic - took over 3 hours of steady playing for this to happen.
Occured again with the Jan 6th. nightly build. Again after several hours of play. It was NOT progressing through the track - that was bad info (a song with 1.5 minutes of silence at the end). Hit back song then forward song and song played fine the second time around. The stuck song was REO Speedwagon - one lonely night. I also tried hitting pause/play this time - no effect. Here is a part of the log file that I THINK may be relavent (more log file attached): [15:17:41.6235] Slim::Player::Source::openSong (1917) Opening file D:\Music\REO Speedwagon\The Essential REO Speedwagon Disk 2\09-One Lonely Night-The Essential REO Speedwagon Disk 2.flac [15:17:41.6257] Slim::Player::Source::openSong (1921) Seeking in 0 into D:\Music\REO Speedwagon\The Essential REO Speedwagon Disk 2\09-One Lonely Night-The Essential REO Speedwagon Disk 2.flac [15:17:41.6278] Slim::Player::Source::openSong (2056) Streaming with format: flc [15:17:41.6573] Slim::Player::Source::playmode (397) 00:04:20:07:60:63 New play mode: play [15:17:41.6806] Slim::Player::Source::playmode (553) 00:04:20:07:60:63: Current playmode: play [15:17:41.7234] Slim::Player::Source::decoderUnderrun (579) 00:04:20:07:60:63: Decoder underrun while this mode: play [15:17:41.7243] Slim::Player::Source::nextsong (1551) The next song is number 65, was 64 [15:17:41.7254] Slim::Player::Source::decoderUnderrun (592) Track failed before playback, marking as played [15:17:41.7263] Slim::Player::Source::nextsong (1551) The next song is number 65, was 64 [15:17:42.5893] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:17:48.6053] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:17:52.5766] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.010s [15:17:58.6674] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:18:06.6363] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:18:13.0184] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.001s [15:18:13.5769] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.011s [15:18:21.5826] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.003s [15:18:24.5773] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.003s [15:18:28.0262] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:3d:bc adjust jiffies epoch -0.009s [15:18:32.6676] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:18:33.0218] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.003s [15:18:39.6679] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.002s [15:18:48.1117] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:18:54.7617] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.004s [15:18:55.5792] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.010s [15:18:58.1846] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:3d:bc adjust jiffies epoch +0.005s [15:19:03.0077] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:3d:bc adjust jiffies epoch -0.007s [15:19:03.0098] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.003s [15:19:09.5772] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.005s [15:19:17.8554] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:19:19.5771] Slim::Player::Player::trackJiffiesEpoch (748) 00:04:20:07:60:63 adjust jiffies epoch -0.005s [15:19:27.6884] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.003s [15:19:28.1492] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:3d:bc adjust jiffies epoch +0.005s [15:19:32.1543] Slim::Player::Source::playmode (298) 00:04:20:07:60:63: Switching to mode pause from play [15:19:32.1556] Slim::Player::Source::playmode (397) 00:04:20:07:60:63 New play mode: pause [15:19:32.1579] Slim::Player::Source::playmode (553) 00:04:20:07:60:63: Current playmode: pause [15:19:32.7683] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:19:35.3738] Slim::Player::Source::playmode (298) 00:04:20:07:60:63: Switching to mode resume from pause [15:19:35.3750] Slim::Player::Source::playmode (397) 00:04:20:07:60:63 New play mode: resume [15:19:35.3773] Slim::Player::Source::playmode (417) 00:04:20:07:60:63: Resume, resetting mode: play [15:19:35.3814] Slim::Player::Source::playmode (553) 00:04:20:07:60:63: Current playmode: resume [15:19:35.4045] Slim::Player::Player::trackJiffiesEpoch (772) 00:04:20:07:60:63 adjust jiffies epoch +0.005s [15:19:41.4343] Slim::Player::Source::playmode (298) 00:04:20:07:60:63: Switching to mode stop from play [15:19:41.4354] Slim::Player::Source::playmode (397) 00:04:20:07:60:63 New play mode: stop [15:19:41.4362] Slim::Player::Source::playmode (442) 00:04:20:07:60:63: Stopping and clearing out old chunks [15:19:41.4392] Slim::Player::Source::resetSong (1590) Resetting song buffer. [15:19:41.4400] Slim::Player::Source::resetSongQueue (1424) Resetting song queue [15:19:41.4407] Slim::Player::Source::resetSongQueue (1434) Song queue is now 64 [15:19:41.4577] Slim::Player::Source::playmode (553) 00:04:20:07:60:63: Current playmode: stop [15:19:41.4585] Slim::Player::Source::jumpto (1156) Jumping by -1 [15:19:41.4592] Slim::Player::Source::streamingSongIndex (1350) Adding song index 63 to song queue [15:19:41.4599] Slim::Player::Source::streamingSongIndex (1354) Clearing out song queue first [15:19:41.4606] Slim::Player::Source::streamingSongIndex (1371) Song queue is now 63 [15:19:41.4619] Slim::Player::Source::playmode (298) 00:04:20:07:60:63: Switching to mode play from stop [15:19:41.4631] Slim::Player::Source::resetSong (1590) Resetting song buffer. [15:19:41.4738] Slim::Player::Source::openSong (1685) Trying to open: file:///D:/Music/Nickelback/Silver%20Side%20Up/10-Good%20Times%20Gone- Silver%20Side%20Up.flac [
Created attachment 2623 [details] Second log file (Jan 6th)
With the two examples, how many more tracks were there in the playlist? It is interesting that in one example it paused and the other it stopped. I do not think that 'off' synced player is having any influence here.
I did hit the pause/play buttons this time instead of a clear back/forward. Hoped that it would provide some additional information. The pause/play had no effect - it didn't start playing again until I did the back. The decoder underrun error was in both of the logs. There were at least a few pages left to play in playlist (100-150 songs). Perhaps more. So in total a couple hundred in the entire playlist or there-abouts.
I think that the root cause here is bug 4019, which causes problems starting FLAC files under some conditions. The resulting, unexpected STMd event (decoder-underrun) is not correctly handled in this case. I may have a patch for this.
Change 16069 should make things keep going when this problem is encountered, but does not fix the underlying firmware bug. Doug, it would be good if you could try with tomorrow's nightly. When the problem occurs then a track will get skipped but the playlist should keep going.
OK. THANKS Will there be something in a log somewhere that I can see if/when the problem occurs? It sounds like it won't be very noticable now if it just jumps over a song. Just checking, but would this one also be causing the other issue mentioned in the forum where someone get static played? I just get silence, but they seemed very close to an outside observer. Mentioned it in case that it is and you hadn't noticed that forum thread.
You could enable logging for player.source=info and see if you get "decoderUnderrun (592) Track failed before playback, marking as played" messages. I do not think that it is likely to be the same problem as the 'just static' one, but I suppose it is possible.
Created attachment 2645 [details] Log file with errors and continuing.
Downloaded and deleted the old log file. Looks like it continues on. There are a LOT of these in the log, though. What is the eta on the firmware fix?
The logfile you uploaded did not show any of these exceptions. Note it is not simply decoderUnderrun that you are looking for, as this is a normal occurance, not an error. You need to look for "decoderUnderrun (592) Track failed before playback, marking as played"
Oh, that's good news, I guess since there were so many of them. I will rerun the test - none found in yesterday's run. Sorry.
OK, that's 2 days now of running and I haven't had the firmware error again. I did notice that I had the player.source logging set to debug instead of info for a while, though. Also, I am playing to a different player. Usually I am playing the main unit and the bedroom unit is off. Now for this test I'm playing the bedroom unit (without the stereo turned on) and the main unit is off. The bedroom unit is sync'd to the main unit (which is off). Not sure if any of this matters to this or the firmware issue, but just in case...
Are either of the players connected over wireless? Are they different types of player? In either case this could effect the results because the firmware bug is a timing problem which could be influenced be either of these points. Debug level is fine - you just get more stuff logged. The point is that info level is sufficient.
They are both SB3s. The bedroom one (the one that apparently doesn't get the issue) is connected with wireless. The main one is wired. I figured that debug had more, but since I wasn't seeing anything I figured that I had better report everything - sorry I didn't think of the connection method. Should any of this info be put into the firmware bug report (4019)? I'll run another test with the main one today.
Created attachment 2650 [details] Third Log
Well, I did get AN error this morning. It was error 590 instead of 592, but the text was the same... Also, not sure that this was a fully valid test because of the following: I also was having connection timeout problems this morning after downloading the current nightly. The main sb3 wouldn't play, I couldn't get to the web interface from a remote computer BUT the same computer would play with softsqueeze... The web interface on the box running SC worked with no issues. From the web interface I could power on/off the main SB3 that wouldn't play. Shutting down SC server, etc. didn't change anything. Connecting the main SB3 to a different SC (older, caused a firmware restart) and back did not change anything. Rebooting the Windows XP box running SC cleared all issues up, though. Only mentioning this in case it is somehow relevant to understanding the log file. After your review, if you feel that this is a valid test then please feel free to mark this as fixed.
Well I must say that your log looks horrible. I think that you had some sort of connection problems going on. But, in any case, it did exercise the fix in an appropriate way, so I'll mark this as fixed (with the rider that the full fix will only come with a firmware fix). The number, by the way, is just the source-code line number, not a specific error number. I hope that you have got your system working again properly now.
Looks like the problem is back - or I just managed to recreate it again. This was again playing for several hours prior to freezing... Uploading log.
Created attachment 2689 [details] 19 Jan Log
My SC version is now: SqueezeCenter Version: 7.0 - 16375 - Windows XP - EN - cp1252
Hmm, I do not know if this is a different manifestation of bug 4019 but the circumstances seem different. Previously, you have had the case that SC got an STMd (decoderUnderrun) before the track started playing. In this case, the track had been playing for 3:33 (from a total duration of 4:36) when SC got the STMd. Very odd. 10s later (the length of the output buffer), SC got STMu (underrun == end of track), followed by STMo (outputUnderrun). The decoder buffer had 3145727 bytes in it and the streaming connection was still open (otherwise there would be no STMo). The STMo triggered a pause-rebuffer-resume sequence but I guess that this did not actually cause the track to continue playing. SC did not skip to the next track in this case because it was already playing the song and not yet in mode 'playout-play' (still in mode 'play'). I am more hesitant about putting a workaround into SC for this case - skipping on when a track fails to play at all is one thing but doing the same when 'something weird' happens in the middle of a track is rather different. Felix, can you comment on this.
The log suggests that the early STMd comes out of the blue. Looking through firmware I only see two cases where a STMd would be sent too early: Either when the stream connection is dropped or when the (flac)-decoder encountered an unrecoverable decoder error. The first would suggest a shaky connection (wireless?) and the second a problematic flac file.
I'm using a wired connection to the one playing. The secondary SB (off, sync'd) is wireless, though. No heavy network traffic was occuring at the time of the interruption. No maintenance activity, either. It was during the day so no Windows update activity, either. The file plays fine other times without an issue. The issue has been noticed on different files each time, I beleive (after I eliminated the song with a couple of minutes of silence at the end...). Is there any other logging that I can/should turn on to assist in tracking this down? This does seem to be very intermittent now - once every couple of days or so. Also, should this be moved to its own bug or anything? Just let me know.
I am beginning to wonder if you have a problem with one of your SB3s. Would it possible for you to swap them over, and continue 'testing' with the wired one. Run with player.source=info and monitor the log from time-to-time to see if you get any abnormal decoderUnderrun events.
Doug, did you get the previous message? Are you able to try swapping your SB3s with each other?
It lost one of my replies - unless I sent it as an e-mail. I switched out the main sb3 with a different one and so far no occurrances of this issue. I also managed to leave it running with the old one (without the avr on) for many hours without it appearing as well. So I'd have to say that this is probably in the one-time fluke catagory right now - or specific hardware. I'll keep an eye on it and setup the orig. sb3 to run constantly with a large playlist over and over for a while to see if it shows up again, but until it does this could probalby be closed, right? Marking it as "works for me".
It went for a week straight playing a very large playlist over and over without the issue reoccurring. Only difference was that there was no audio equipment attached to it and nothing was synchronized to it. The new one in the main location has not experience the lockup either. Looks fully gone as of now anyway.
I have amazing timing. Of course it has done it several times today. To the main device (the new one so that eliminates hardware). The only change is that the bedroom unit is sync'd and on today and I installed this morning's nightly. I was running the SyncOptions plug in the first couple of times but I disabled it for the last couple.
It occurred starting to play Faith Hill's "One Cry". I had to virtually "power down" the main player and then turn it back on (from the web UI) before it would start playing the track again. Once it was turned back on the track played with no further issues. The bedroom unit was not changed/controlled in any way during this time. The main unit is connected with a wired network cable, the bedroom unit is connected wirelessly. Attaching log file excerpt.
Created attachment 2833 [details] Log Excerpt Feb. 9th
Do you need additional logs/information from me on this to research it further? Since it doesn't appear that it will be addressed shortly any suggestions on how I might be able to work around the issue in the meantime? It is rather inconvienent. thanks.
Doug, how often are you tripping over this?
The trigger seems to be the fact that one of your players (in the sync group) keeps disconnecting from SC on the control channel. The evidence for this are the following lines in your trace output: Slim::Networking::Slimproto::slimproto_close (257) Player disconnected, temporary unsync 00:04:20:07:3d:bc I do not know what is causing these regular disconnections. I think that you must have some kind of problem, either with that player or the network. Once they happen, I have found several areas where the reconnection might result in the player and SC having different ideas about each other's state. This then leads to the lockup that you have observed. These cases will only happen when synced. I will probably have change for this shortly but am not entirely sure just what failure case is triggered for you, so I cannot be sure that it will solve the problem.
Marking this fixed (again) with change 18539.
Well, I switched and substituted players around so I don't THINK that it is hardware. One of the players was using a wireless network - those tend to have brief interruptions so I'd tend to think that was the guilty party. Since the other was using a wired network it wouldn't have experienced the drop. THANKS! P.S. Sorry I missed your question in mid-march - don't know how that happened.
(In reply to comment #41) > Well, I switched and substituted players around so I don't THINK that it is > hardware. One of the players was using a wireless network - those tend to have > brief interruptions so I'd tend to think that was the guilty party. Since the > other was using a wired network it wouldn't have experienced the drop. > THANKS! > P.S. Sorry I missed your question in mid-march - don't know how that happened. > Marking bug as verified & closing. Please reopen the bug with new details if you see this problem happen again.
Reduce number of active targets for SC