Bugzilla – Bug 4098
Wrong time after scanning through a file / scanning short songs jumps to next track
Last modified: 2009-09-08 09:13:57 UTC
I have a directory with many mp3 files. I use music folder to go to that directory. Play the first file. As it nears the end, press and hold add. File is moved to zapped files, and next file start to play. The position is not reset to zero, but rather to some random value between zero and the file length. If I stop everything and navigate to the file and play it it starts at zero.
I couldn't seem to reproduce this. Ross, can you have a look? Marc, does this happen with any MP3 files or only some?
well i can't reliably reproduce it either. it seems the same pattern sometimes fails, sometimes not. i did get it to fail again - then same attempt didn't! i'm confused. i'll close this for now and play with it - when I figure it out I'll reopen with a more reliable test case.
Try using d_source if it can be reproduced, possibly also d_command (for marking when the zap command is processed
Ross, I'd still like you to have a go at this. Turn on d_source and d_command beforehand as KDF suggests.
Marc I'm confused about this comment: "File is moved to zapped files, and next file start to play. The position is not reset to zero, but rather to some random value between zero and the file length." What song doesn't start at the beginning, the song that follows when you press and hold +? I'm not seeing that. I've waited until the song is about to end and held the add button, it adds the song to my zapped playlist, and the next song starts from the beginning as I would expect it to. If I've correctly described the bug, then I'm unable to reproduce it.
The next file starts at the beginning but the position shown in now playing is some random value well greater than zero.
Marc, Thanks for clarifying. I've just tried this 8 times and everytime it brings me to the next song, starts at the beginning, and the now playing bar starts at the beginning. Still unable to reproduce this. Does anyone think it might be the files? Would it be worth having Marc send us some sample files to try?
Let's just leave it for now. If a user sees the issue then we or they can reopen it.
I think I can reproduce this reliable with the following seguence. Go via music folder to a directory with two or more tracks. Press right once more to go to the first track. Press play. While playing, hold fwd down to go into fast fwd (2x) mode. Then press play again. Then press and hold add to move the track to zapped. Next track will display the offset that the first was at. And the offset is pretty sticky. It even shows up if you start an internet radio station. The only way I've found to clear it is to use song scanner to manually set the offset to zero again. If necessary, I will provide the two mp3 traces, but they are just mp3's ripped from a CD. Here is some of the log d_command and d_source switching rate from 2 to 1 rate change, jumping to the current position in order to restart the stream resetSong openSong on: file:////aptiva/home/marc/BigStuff/RIPDIR/Music/TestCase/AlbanBerg%20Quartet%20Opus%203%20Movement%201.mp3 openSong: duration: [582.557] size: [9320907] endian [] offset: [1599] for file:////aptiva/home/marc/BigStuff/RIPDIR/Music/TestCase/AlbanBerg%20Quartet%20Opus%203%20Movement%201.mp3 Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 undermax = 1, type = mp3, squeezebox2 = 00:04:20:06:3e:0a checking formats for: mp3-wma-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-wma-*-00:04:20:06:3e:0a checking formats for: mp3-wma-squeezebox2-* checking formats for: mp3-wma-*-* checking formats for: mp3-ogg-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-ogg-*-00:04:20:06:3e:0a checking formats for: mp3-ogg-squeezebox2-* checking formats for: mp3-ogg-*-* checking formats for: mp3-flc-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-flc-*-00:04:20:06:3e:0a checking formats for: mp3-flc-squeezebox2-* checking formats for: mp3-flc-*-* checking formats for: mp3-aif-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-aif-*-00:04:20:06:3e:0a checking formats for: mp3-aif-squeezebox2-* checking formats for: mp3-aif-*-* checking formats for: mp3-wav-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-wav-*-00:04:20:06:3e:0a checking formats for: mp3-wav-squeezebox2-* checking formats for: mp3-wav-*-* checking formats for: mp3-mp3-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-mp3-*-00:04:20:06:3e:0a checking formats for: mp3-mp3-squeezebox2-* checking formats for: mp3-mp3-*-* Checking to see if mp3-mp3-*-* is enabled enabled Found command: - Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 Matched Format: mp3 Type: mp3 Command: - openSong: this is an mp3 file: file:////aptiva/home/marc/BigStuff/RIPDIR/Music/TestCase/AlbanBerg%20Quartet%20Opus%203%20Movement%201.mp3 file type: mp3 format: mp3 inrate: 128 maxRate: 0 command: - openSong: opening file \\aptiva\home\marc\BigStuff\RIPDIR\Music\TestCase\AlbanBerg Quartet Opus 3 Movement 1.mp3 openSong: seeking in 1599 into \\aptiva\home\marc\BigStuff\RIPDIR\Music\TestCase\AlbanBerg Quartet Opus 3 Movement 1.mp3 openSong: Streaming with format: mp3 findFrameBoundaries: start: [470131] end: [0] time2offset: 29.3744126467054 to 470131 (align: 1 size: 9320907 duration: 582.557) gototime: going to time 29.3744126467054 gototime: stopping playback gototime: restarting playback Request: Command [00:04:20:06:3e:0a->rate] (Done) Param: [_newvalue] = [1] Request: Command [00:04:20:06:3e:0a->button] (Done) Param: [_buttoncode] = [play] Param: [_time] = [340192.819] Param: [_orFunction] = [1] Got a track starting event Song 0 has now started playing Song queue is now 0 Got a track starting event Song 0 has now started playing Song queue is now 0 Request: Command [00:04:20:06:3e:0a->button] (Done) Param: [_buttoncode] = [] Param: [_time] = [340196.333] Param: [_orFunction] = [1] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.333] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.441] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.549] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.657] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.765] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.874] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340196.982] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.09] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.198] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.306] Removing currently playing track. 00:04:20:06:3e:0a: Switching to mode stop from play 00:04:20:06:3e:0a New play mode: stop Stopping and clearing out old chunks for client 00:04:20:06:3e:0a resetSong Resetting song queue Song queue is now 0 00:04:20:06:3e:0a: Current playmode: stop 00:04:20:06:3e:0a: Switching to mode stop from stop Already in playmode stop : ignoring mode change Adding song index 0 to song queue Clearing out song queue first Song queue is now 0 00:04:20:06:3e:0a: Switching to mode play from stop resetSong openSong on: file:////aptiva/home/marc/BigStuff/RIPDIR/Music/TestCase/AlbanBerg%20Quartet%20Opus%203%20Movement%202.mp3 openSong: duration: [649.117] size: [10385867] endian [] offset: [1599] for file:////aptiva/home/marc/BigStuff/RIPDIR/Music/TestCase/AlbanBerg%20Quartet%20Opus%203%20Movement%202.mp3 Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 undermax = 1, type = mp3, squeezebox2 = 00:04:20:06:3e:0a checking formats for: mp3-wma-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-wma-*-00:04:20:06:3e:0a checking formats for: mp3-wma-squeezebox2-* checking formats for: mp3-wma-*-* checking formats for: mp3-ogg-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-ogg-*-00:04:20:06:3e:0a checking formats for: mp3-ogg-squeezebox2-* checking formats for: mp3-ogg-*-* checking formats for: mp3-flc-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-flc-*-00:04:20:06:3e:0a checking formats for: mp3-flc-squeezebox2-* checking formats for: mp3-flc-*-* checking formats for: mp3-aif-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-aif-*-00:04:20:06:3e:0a checking formats for: mp3-aif-squeezebox2-* checking formats for: mp3-aif-*-* checking formats for: mp3-wav-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-wav-*-00:04:20:06:3e:0a checking formats for: mp3-wav-squeezebox2-* checking formats for: mp3-wav-*-* checking formats for: mp3-mp3-squeezebox2-00:04:20:06:3e:0a checking formats for: mp3-mp3-*-00:04:20:06:3e:0a checking formats for: mp3-mp3-squeezebox2-* checking formats for: mp3-mp3-*-* Checking to see if mp3-mp3-*-* is enabled enabled Found command: - Setting maxBitRate for FamilyRoom to: 0 Setting maxBitRate for FamilyRoom to: 0 Matched Format: mp3 Type: mp3 Command: - openSong: this is an mp3 file: file:////aptiva/home/marc/BigStuff/RIPDIR/Music/TestCase/AlbanBerg%20Quartet%20Opus%203%20Movement%202.mp3 file type: mp3 format: mp3 inrate: 128 maxRate: 0 command: - openSong: opening file \\aptiva\home\marc\BigStuff\RIPDIR\Music\TestCase\AlbanBerg Quartet Opus 3 Movement 2.mp3 openSong: seeking in 1599 into \\aptiva\home\marc\BigStuff\RIPDIR\Music\TestCase\AlbanBerg Quartet Opus 3 Movement 2.mp3 openSong: Streaming with format: mp3 00:04:20:06:3e:0a New play mode: play 00:04:20:06:3e:0a: Current playmode: play Request: Command [00:04:20:06:3e:0a->playlist delete] (Done) Param: [_index] = [0] Request: Command [00:04:20:06:3e:0a->playlist zap] (Done) Param: [_index] = [0] Request: Command [00:04:20:06:3e:0a->button] (Done) Param: [_buttoncode] = [zap] Param: [_time] = [340197.414] Param: [_orFunction] = [1] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.414] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.522] We need to send 0 seconds of silence... sending 0 bytes of silence Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.63] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.739] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689609f] Param: [_time] = [340197.847] Got a track starting event Song 0 has now started playing Song queue is now 0 Request: Command [00:04:20:06:3e:0a->button] (Done) Param: [_buttoncode] = [left] Param: [_time] = [340202.81] Param: [_orFunction] = [1] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689906f] Param: [_time] = [340202.81] Request: Command [00:04:20:06:3e:0a->ir] (Done) Param: [_ircode] = [7689906f] Param: [_time] = [340202.918] Request: Command [00:04:20:06:3e:0a->ir] (Done)
I am seeing this bug now while qualifying fw63 although it doesn't look like a fw bug. This looks very bad. I also had to scan before seeing it, but now the progress bar and clock is totally fubar. However, I did not have to zap the file, so I changed the summary of the bug.
also cc'ing Dan
Adding Andy, in case he has any ideas.
Fred, can you check this out? This looks like it is caused by your change 9331.
Simpler repro steps, you don't need to zap a track: * Play mp3 * FF 2x for a bit * Play (songStartStreamTime is now set to a different offset) * Skip to next track songStartStreamTime is not reset to 0 in this case.
I've reverted change 9331, so this bug appears fixed now.
*** Bug 3977 has been marked as a duplicate of this bug. ***
Reverting my change did not fix the underlying issue. This must be reopened. Find a short song and try fast forwarding through it. About 50% of times, you skip to the next song when 30s remain (not sure why). If you're not and you press play, the time will be wrong for the last 15 seconds of the track. The cause of the second bug is obvious: songStartStreamTime is RESET when the song STARTS STREAMING but it is used to calculate time into the PLAYING song. That just cannot work when the two aren't the same (at the very end of the song, when you're playing N and streaming N+1). This bug is the same as bug 3977: gototime is broken. Fred
If for some reason we can't get a complete fix, I'd rather have small songs skip ahead when there's 30 seconds left than have ffwd in arbitrary songs cause the time display to be incorrect for a while. It seems like the lesser bug to me.
Agreed. Thinking about it, though, the displayed time will be wrong for the last 15 seconds or so for any song you fast forward into. If songStartStreamTime is not 0, whatever the reason (fast forwarding or using the CLI time command), the displayed/reported time is wrong at the end of the song. I don't know enough of the streaming logic to take the chance to fix that for 6.5.
So, just to refresh my memory, the status of this currently is: if there is a short file and try to scan forward, slimserver skips ahead to the next track? Shall I change the summary to reflect this fact (since you regressed the change that caused the larger bug)?
Chris, you are correct, but there's more to it. Comments 17 and 19 apply... -Fast forwarding on short songs sometimes skip forward to the next song. -Fast forwarding (or using CLI goto time) results in the displayed time to be wrong at the end of the song (from the moment the NEXT song starts stream, i.e. about 15s before the end of the song with a SB3). So it's really 2 issues, but it's likely a fix for one solves the other.
thanks very much for summarizing the remaining issues, Fred! For anyone looking at this one, I was able to still reproduce it following Marc's instructions in comment 9 (although the zapping is not required). I tested with a 7 min flac file, listening to a few seconds to make sure it was playing, then scanning fwd (8x) to about the middle. I then pressed 'play' to listen to the rest of the track in real time. As I pressed the play button, I noticed the bar graph jumped backwards slightly. At the end of the song, the clock counted down (I had it set to show remaining time) to -0:06, then rolled over to -5:12 as the song continued playing for another 10 seconds. It's not clear to me where that -5:12 number came from. It's not the length of the next track.
Dean suggests Alan Young can look at this.
Is he a mind-reader? I just about have a fix ready!
change 14077 fixes this for players that report songElasedSeconds. I have not attempted to fix this for older players (SliMP3 & SB1) and Web Clients (is it even relevant for Web Clients?). Note that with VBR streams, the calculations that FFWD/REW and gotoTime make to jump to a position in the file, on the assumption time is proportional to bytes, can be off by a significant margin. Some quick tests on a few of my files reveal differences in the order of +/- 8 seconds. In these cases the counter may be off by up to that amount.
This bug is being closed since it was resolved for a version which is now released! Please download the new version of SqueezeCenter (formerly SlimServer) at http://www.slimdevices.com/su_downloads.html If you are still seeing this bug, please re-open it and we will consider it for a future release.