Bugzilla – Bug 3899
Softsqueeze: Can't reliably fast forward/rewind through the playing track
Last modified: 2008-09-11 08:54:44 UTC
When I press and hold "fwd" to fast forward through the currently playing track, I find that slimserver frequently skips over the track and plays the next track in the playlist. I suspect the player is detecting the remote control button hold action, but frequently also does the single button press action when the button is released.
Hi Philip, sometimes it is the simple things. Have you tried new batteries? :)
I get the same effect with Softsqueeze.
Okay. So you see this both on softsqueeze and on an SB3? Try as I might I couldn't reproduce this on either SB2 or SB3 hardware. I'll try softsqueeze in a bit. Does the log show anything interesting if you turn on maybe d_ir, d_slimproto, and d_source?
Yes, I saw this initially on a SB3. Nb. I have my display format to display a progress bar - it's more obvious to see the fault in this mode. I repeated it on SoftSqueeze 3.0b2. The track I tested with was mp3, 256kbps CBR, with a Volume Adjustment of 2.98 dB. This track also causes distorted sound via SoftSqueeze playback. Often, going to x2 isn't a problem, but x4 will cause the instant jump to the next song. I just tried a track from a different album (mp3, 167kbps VBR), and the effect is different! All kind of strange things happen. I still see the jumping to next track issue, but sometimes it seems to play both the previous and next track simultaneously! Sometimes after stopping fast forward (by pressing play), it sounds like fast forward is still active. Sometimes I see the progress bar fill, indicating that the track has been skipped to the end, but it will still continue to play the current track, until I press play to come out of fast forward mode, which causes the next track to play. It's hard to detail exact steps, as it does something different each time I try to do the same thing! I would say that fast forward works correctly about 5% of the time for me.
I turned on the requested debug options and repeated the problem. It generated a lot of output. I can see several backtraces in my log. Here's a section from the log: 2006-08-10 00:12:16.9253 Setting maxBitRate for Study to: 0 2006-08-10 00:12:16.9258 Setting maxBitRate for Study to: 0 2006-08-10 00:12:16.9260 undermax = 1, type = mp3, softsqueeze = 5e:31:13:06:25:02 2006-08-10 00:12:16.9263 checking formats for: mp3-ogg-softsqueeze-5e:31:13:06:25:02 2006-08-10 00:12:16.9265 checking formats for: mp3-ogg-*-5e:31:13:06:25:02 2006-08-10 00:12:16.9267 checking formats for: mp3-ogg-softsqueeze-* 2006-08-10 00:12:16.9270 checking formats for: mp3-ogg-*-* 2006-08-10 00:12:16.9272 checking formats for: mp3-flc-softsqueeze-5e:31:13:06:25:02 2006-08-10 00:12:16.9274 checking formats for: mp3-flc-*-5e:31:13:06:25:02 2006-08-10 00:12:16.9276 checking formats for: mp3-flc-softsqueeze-* 2006-08-10 00:12:16.9278 checking formats for: mp3-flc-*-* 2006-08-10 00:12:16.9281 checking formats for: mp3-aif-softsqueeze-5e:31:13:06:25:02 2006-08-10 00:12:16.9283 checking formats for: mp3-aif-*-5e:31:13:06:25:02 2006-08-10 00:12:16.9285 checking formats for: mp3-aif-softsqueeze-* 2006-08-10 00:12:16.9287 checking formats for: mp3-aif-*-* 2006-08-10 00:12:16.9289 checking formats for: mp3-wav-softsqueeze-5e:31:13:06:25:02 2006-08-10 00:12:16.9291 checking formats for: mp3-wav-*-5e:31:13:06:25:02 2006-08-10 00:12:16.9294 checking formats for: mp3-wav-softsqueeze-* 2006-08-10 00:12:16.9300 checking formats for: mp3-wav-*-* 2006-08-10 00:12:16.9303 checking formats for: mp3-mp3-softsqueeze-5e:31:13:06:25:02 2006-08-10 00:12:16.9306 checking formats for: mp3-mp3-*-5e:31:13:06:25:02 2006-08-10 00:12:16.9308 checking formats for: mp3-mp3-softsqueeze-* 2006-08-10 00:12:16.9310 checking formats for: mp3-mp3-*-* 2006-08-10 00:12:16.9312 Checking to see if mp3-mp3-*-* is enabled 2006-08-10 00:12:16.9314 enabled 2006-08-10 00:12:16.9316 Found command: - 2006-08-10 00:12:16.9319 Setting maxBitRate for Study to: 0 2006-08-10 00:12:16.9322 Setting maxBitRate for Study to: 0 2006-08-10 00:12:16.9324 Matched Format: mp3 Type: mp3 Command: - 2006-08-10 00:12:16.9326 playing out before starting next song. (old format: mp3, new: mp3) 2006-08-10 00:12:16.9329 5e:31:13:06:25:02: Switching to mode playout-play from play 2006-08-10 00:12:16.9334 5e:31:13:06:25:02 New play mode: playout-play 2006-08-10 00:12:16.9340 Use of uninitialized value in concatenation (.) or string at P:\Music\SlimServer\trunk\server/Slim/Player/Squeezebox.pm line 595. 2006-08-10 00:12:16.9344 Use of uninitialized value in concatenation (.) or string at P:\Music\SlimServer\trunk\server/Slim/Player/Squeezebox.pm line 595. 2006-08-10 00:12:16.9347 Use of uninitialized value in concatenation (.) or string at P:\Music\SlimServer\trunk\server/Slim/Player/Squeezebox.pm line 595. 2006-08-10 00:12:16.9350 *************stream called: u paused: format: url: 2006-08-10 00:12:16.9354 Backtrace: frame 0: Slim::Player::Squeezebox::stream (P:\Music\SlimServer\trunk\server/Slim/Player/Squeezebox.pm line 179) frame 1: Slim::Player::Squeezebox::resume (P:\Music\SlimServer\trunk\server/Slim/Player/Source.pm line 443) frame 2: Slim::Player::Source::playmode (P:\Music\SlimServer\trunk\server/Slim/Player/Source.pm line 930) frame 3: Slim::Player::Source::gotoNext (P:\Music\SlimServer\trunk\server/Slim/Player/Source.pm line 1789) frame 4: Slim::Player::Source::readNextChunk (P:\Music\SlimServer\trunk\server/Slim/Player/Source.pm line 661) frame 5: Slim::Player::Source::nextChunk (P:\Music\SlimServer\trunk\server/Slim/Web/HTTP.pm line 1672) frame 6: Slim::Web::HTTP::sendStreamingResponse (P:\Music\SlimServer\trunk\server/Slim/Networking/Select.pm line 170) frame 7: Slim::Networking::Select::select (P:\Music\SlimServer\trunk\server\slimserver.pl line 493) frame 8: main::idle (P:\Music\SlimServer\trunk\server\slimserver.pl line 446) frame 9: main::main (P:\Music\SlimServer\trunk\server\slimserver.pl line 1043) 2006-08-10 00:12:16.9361 starting with decoder with format: m autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? 2006-08-10 00:12:16.9363 flags: 0 2006-08-10 00:12:16.9366 sending strm frame of length: 24 request string: 2006-08-10 00:12:16.9381 5e:31:13:06:25:02: Current playmode: playout-play 2006-08-10 00:12:16.9384 No pending chunks - we're dropping the streaming connection 2006-08-10 00:12:16.9395 5e:31:13:06:25:02: Can't opennext, returning no chunk. 2006-08-10 00:12:16.9411 Use of uninitialized value in delete at P:\Music\SlimServer\trunk\server/Slim/Networking/Select.pm line 108. 2006-08-10 00:12:16.9422 getpeername() on closed socket GEN62 at P:/Programming/Perl/lib/IO/Socket.pm line 206. 2006-08-10 00:12:16.9433 Squeezebox got disconnection on the data channel why: Connection closed normally 2006-08-10 00:12:16.9535 5e:31:13:06:25:02 Squeezebox stream status: event_code: STMs bytes_rec_H 0 bytes_rec_L 413755 fullness: 397371 (37%) bufferSize 1048576 fullness 397371 bytes_received 413755 jiffies: 67407 2006-08-10 00:12:16.9539 output size: 3528000 output fullness: 0 elapsed seconds: 0 2006-08-10 00:12:16.9542 Got a track starting event 2006-08-10 00:12:16.9544 Song 3 has now started playing 2006-08-10 00:12:16.9551 Song queue is now 3 2006-08-10 00:12:16.9567 IR: 7689a05f -> code: fwd 2006-08-10 00:12:16.9570 7689a05f 67.407 1155165136.95703 2006-08-10 00:12:16.9573 found button fwd for 7689a05f 2006-08-10 00:12:16.9576 irCode not defined: fwd.repeat 2006-08-10 00:12:16.9578 irCode = [] timer = [67.407] timediff = [0.0939999999999941] last = [scan_fwd] 2006-08-10 00:12:16.9598 Use of uninitialized value in string eq at P:\Music\SlimServer\trunk\server/Plugins/DynamicPlayList/Plugin.pm line 1047. 2006-08-10 00:12:16.9603 Use of uninitialized value in concatenation (.) or string at P:\Music\SlimServer\trunk\server/Plugins/DynamicPlayList/Plugin.pm line 1051. 2006-08-10 00:12:17.0491 IR: 7689a05f -> code: fwd 2006-08-10 00:12:17.0496 7689a05f 67.5 1155165137.04958 2006-08-10 00:12:17.0498 found button fwd for 7689a05f 2006-08-10 00:12:17.0501 irCode not defined: fwd.repeat 2006-08-10 00:12:17.0504 irCode = [] timer = [67.5] timediff = [0.0930000000000035] last = [scan_fwd] 2006-08-10 00:12:17.1276 5e:31:13:06:25:02 Squeezebox stream status: event_code: STMu bytes_rec_H 0 bytes_rec_L 413755 fullness: 397371 (37%) bufferSize 1048576 fullness 397371 bytes_received 413755 jiffies: 67579 2006-08-10 00:12:17.1280 output size: 3528000 output fullness: 0 elapsed seconds: 0 2006-08-10 00:12:17.1283 5e:31:13:06:25:02: Underrun while this mode: playout-play 2006-08-10 00:12:17.1285 **skipahead: opening next song 2006-08-10 00:12:17.1287 opening next song... 2006-08-10 00:12:17.1291 the next song is number 4, was 3 2006-08-10 00:12:17.1300 Setting maxBitRate for Study to: 0 2006-08-10 00:12:17.1303 Setting maxBitRate for Study to: 0
Okay that definitely does NOT look like the remote signals are being interpreted incorrectly. That looks a lot more like the squeezebox (or softsqueeze?) is having real connection problems. Which for softsqueeze is very, very odd!
Phil - can you attach that VBR file to the bug? Thanks
I just tried to repeat this problem again with the latest v7.0 from SVN. I couldn't cause the problem on a squeezebox playing mp3 CBR files now, but noticed it once with a mp3 VBR file. I'll attach it. However, I can get all types of files to exhibit the fast-forward problem a lot easier in SoftSqueeze. I suspect therefore that the problem exists for all types of files, but that it's now for whatever reason harder to break using a SqueezeBox and standard remote. A new effect that I saw on both SqueezeBox and SoftSqueeze whilst messing about with fast-forward is that the player sometimes starts to play all tracks from a fixed start position. I was trying to get fast-forward to fail. After a while I noticed that when I tried to replay the current track by pressing play or a single-tap rewind, the song returned to 4:40. When I went forward to the next track, it started to play at 4:40. As a result, I couldn't skip to previous track, as the player thought it was half way through the current track, it would always restart the current track instead. I think I got out of this problem by fast-forwarding to the end of the track. There's nothing special with 4:40 - I saw it stick again at other time positions. Also, if I get up to eg x16 fast-forward and then press rewind, I would expect the fast-forwarding slow down, ie. to reduce to x8, but it jumps instantly to rewind at -x2. I'm not sure if it has always done this, but it seems an abnormal behaviour.
Created attachment 1498 [details] mp3 VBR file that didn't fast-forward correctly It took a few attempts, but I got strange fast-forward effects with this file. Press-and-hold FWD a few times, and occasionally it would skip to end of track instead of going up to the next speed. I saw the progress bar instantly fill up before the next track would start.
Ross could you try to repro this with the attached file?
SlimServer 6.5b1 - 9491 - XP I wasn't able to reproduce this with SoftSqueeze or my SB3. I'm guessing because this is an issue with SoftSqueeze as well as Squeezebox, that it's not worth trying another remote. Just to clarify, you're saying that some of the times when you switch from 2x to 4x the song skips? I've tried FWD 2x-32x without problems, and I also tried RWD 2x-16x, and it's behaving exactly as I would anticipate.
I can get it to fail all the time with SoftSqueeze. I haven't seen it fail on a SqueezeBox for quite a while now. I just tried again with the latest SVN, Softsqueeze 3.0b3. Same issues. I find the first few skips forward are okay, eg. going to x2 then x4, but once it goes wrong, there's all sorts of problems. I see the progress bar jump to 100% full - that's the sign that it's started to go wrong. Try holding down the FF button for several seconds and release, and then FF again but release button as soon as you see it go to x4. Long FF.hold events seem to trigger the skip-to-end problem more often that short FF.hold events. It's random, but very repeatable.
Ok, if this is just a SoftSqueeze issue, we need to punt it.
Richard, any thoughts?
Richard?
This won't make 6.5.1, I'll look at it in the future.
i can confirm this. this seems to be very similar to the problem i am experiencing. since the bug is still open, i am going to add myself to it. i posted a thread in the forum a while ago, but so far i got no useful answer. http://forums.slimdevices.com/showthread.php?p=178537 i have the problems on both my SB3 and softsqueeze. even though the static bursts are much louder and more annoying on the SB3. in softsqueeze they only sound like slight garbling. but both will stop scanning at any arbitrary point in the song and skip on to the next track. even the the display sometimes seems to get garbled up (progress bar goes to "full" immediately, "now playing" does not advance to show the new track when it skips, etc.),
After a period of time where FWD/REW seemed more reliable, I have started to notice this again, but the sympoms are a little different. I started a long track (32mins). I got up to 8x FWD. It was skipping through the track fine. I tried to go a bit faster, but when I pressed FWD.hold I got a rebuffering message on the player UI. The message stayed on the screen. When I went back to the Now Playing screen, I could see the play position was at 100% of the track (i.e. it had skipped to the end of the track, but had not moved to the next song. It should not have got as far as the end of the track. I pressed Stop. The track started to play from the start of the track again. I am seeing this consistently. When it goes wrong, it always gets stuck on "Rebuffering 39%", although it is random as to what level of FWD it decides to skip to the end of the track on. Soft Squeeze FWD/REW fails in a different way. It seems to skip forwards to the next track, rather than get stuck at the end of the track on the rebuffering message. If I play track 1 of 5, and try to fast forward through the first track, I can see the screen display new track titles, rather than fast forward. Before I know it, it has reached the end of the playlist. I think that SlimServer needs to be looked at before Richard looks at SoftSqueeze. This bug should be reassigned. SlimServer Version: 6.5.4 - TRUNK
I tried to change the version to 6.5.4, but the change won't stick. Severity is probably higher than minor too... I also notice in SoftSqueeze that after fast forwarding had gone wrong and I have stopped the playback and queued up something else, that the first line of the Now Playing screen reads "NOW SCANNING 8X", when it is not.
Do you still see this problem? The fix to bug 4760 (change 14773) may be relevant.
I have moved to 7.1/trunk, and thus have the new scanner code now. Seems more reliable. I suggest this is closed, and I'll raise any new bugs if errors occur after the new scanner code is released.
(In reply to comment #21) > I have moved to 7.1/trunk, and thus have the new scanner code now. Seems more > reliable. > > I suggest this is closed, and I'll raise any new bugs if errors occur after the > new scanner code is released. > Marking bug as Closed