Bugzilla – Bug 4019
SB2 plays wrong track ,says it's playing correct track
Last modified: 2013-05-17 18:31:25 UTC
CC3.2/ 6.5 r9261/SB2/FLAC It seems possible under certain circumstances to have the SB2 playing track 'n+1' in the playlist, whilst reporting that it's playing track 'n' (which is the correct track). The progess bar and track n details are shown on the player display. Once in this mode, pressing 'play' plays track 'n' and 'fwd' plays track 'n+1'. To get this mode, the sequence seems to be something like this:- Play an Album. Whilst playing say track 1, press 'fwd' a couple of times fairly quickly to move down the playlist two songs. The player will display track 3 with the progess bar and will pause for an unusually long time (2-3 seconds), before starting to play. It will actually play track 4 although the progress bar and display indicate that it's playing track 3. This seems to be repeatable although not 100% consistently. I'm not sure whether the speed of the fwd key presses is significant.
Do you have multiple players attached to slimserver, Patrick? I've noticed some symptoms in the past that are reminiscent of what you are reporting here.
No - one only. I can also get it to do similar with RWD as well as FWD. I've spotted it a few times with 6.5b1, but never quite tracked down how it happened.
It seems non-trivial to reproduce. What are your repeat and shuffle settings?
Repeat = OFF Shuffle = OFF I can repeat it regularly - if not consistently. If it's something to do with say, an IR Proc race, it will depend on the server, load etc and will vary from installation to installation. Hardware InformationProcessors 1 Model AMD Athlon(tm) 64 Processor 3200+ Chip MHz 2000.25 MHz Cache Size 512 KB System Bogomips 3940.35 PCI Devices 00:0f.0 IDE interface: VIA Technologies, Inc. VT8251 AHCI/SATA 4-Port Controller 00:0f.1 IDE interface: VIA Technologies, Inc. VT82C586A/B/VT82C686/A/B/VT823x/A/C PIPC Bus Master IDE 00:11.5 Multimedia audio controller: VIA Technologies, Inc. VT8233/A/8235/8237 AC97 Audio Controller 00:12.0 Ethernet controller: VIA Technologies, Inc. VT6102 [Rhine-II] 01:00.0 VGA compatible controller: VIA Technologies, Inc. S3 Unichrome Pro VGA Adapter IDE Devices hda: Maxtor 6L250R0 (Capacity: 233.76 GB) SCSI Devices ATA Maxtor 6B200M0 (Direct-Access) ATA Maxtor 6B200M0 (Direct-Access) USB Devices Linux 2.6.9-test2 uhci_hcd UHCI Host Controller 0000:00:10.3 Linux 2.6.9-test2 uhci_hcd UHCI Host Controller 0000:00:10.2 Linux 2.6.9-test2 uhci_hcd UHCI Host Controller 0000:00:10.1 Linux 2.6.9-test2 uhci_hcd UHCI Host Controller 0000:00:10.0 Linux 2.6.9-test2 ehci_hcd EHCI Host Controller 0000:00:10.4
Chris, have you managed to reproduce this?
Negative. Why don't I see if our other tester has more luck. Ross, could you have a look? And if you do see it, try to figure out why I don't? :)
Please let me know what debug to run to try and pick it up. I'm using a standalone MySQL if that's relevent.
d_source, d_slimproto and d_playlist might prove educational to look at.
Created attachment 1501 [details] Logfile with d_playlist, d_slimproto, d_source enabled
Created attachment 1502 [details] Logfile with d_playlist, d_slimproto, d_source enabled
Playlist:- 1. 1-1. The Scent Of Magnolia by David Sylvian from Everything and Nothing 2. 1-2. Heartbeat (Tainai Kaiki II) by David Sylvian from Everything and Nothing 3. 1-3. Blackwater by David Sylvian from Everything and Nothing 4. 1-4. Albuquerque (Dobro #6) by David Sylvian from Everything and Nothing 5. 1-5. Ride by David Sylvian from Everything and Nothing 6. 1-6. The Golden Way by David Sylvian from Everything and Nothing 7. 1-7. Ghosts by David Sylvian from Everything and Nothing 8. 1-8. Pop Song by David Sylvian from Everything and Nothing 9. 1-9. Every Colour You Are by David Sylvian from Everything and Nothing 10. 1-10. Wanderlust by David Sylvian from Everything and Nothing 11. 1-11. God's Monkey by David Sylvian from Everything and Nothing 12. 1-12. Let The Happiness In by David Sylvian from Everything and Nothing 13. 1-13. I Surrender by David Sylvian from Everything and Nothing 14. 1-14. Thoroughly Lost To Logic by David Sylvian from Everything and Nothing 15. 2-1. Jean The Birdman by David Sylvian from Everything and Nothing 16. 2-2. Cover Me With Flowers by David Sylvian from Everything and Nothing 17. 2-3. The Boy With The Gun by David Sylvian from Everything and Nothing 18. 2-4. Riverman by David Sylvian from Everything and Nothing 19. 2-5. Aparna And Nimisha (Dobro#5) by David Sylvian from Everything and Nothing 20. 2-6. Midnight Sun by David Sylvian from Everything and Nothing 21. 2-7. Orpheus by David Sylvian from Everything and Nothing 22. 2-8. Some Kind Of Fool by David Sylvian from Everything and Nothing 23. 2-9. Cries And Whispers by David Sylvian from Everything and Nothing 24. 2-10. Godman by David Sylvian from Everything and Nothing 25. 2-11. Laughter And Forgetting by David Sylvian from Everything and Nothing 26. 2-12. Buoy by David Sylvian from Everything and Nothing 27. 2-13. Weathered Wall by David Sylvian from Everything and Nothing 28. 2-14. Bamboo Houses by David Sylvian from Everything and Nothing 29. 2-15. Come Morning by David Sylvian from Everything and Nothing Logfile:- attached Reality:- At this point it's telling me (on both web (Fishbone) & Player UI) that it's playing Track 7 (Ghosts) when it's actually playing the next song in the Playlist (Pop Song). I always know when it's going to do this because there's an unusually long pause before it begins playing the song.
One thing I notice in this log is this: 17:46:18 - Ghosts track is opened 17:46:23 - end of file on Ghosts track So it thinks it streamed the whole 20MB file in only 5 seconds. Is 5 seconds about the delay you experience? I assume you never heard any part of the Ghosts track being played?
5 seconds is probably about right - I'd have guessed 2 or 3, but probably 5. It seems to count 1 or 2 seconds on the progressbar (without any music) before dropping back to zero and playing the next track - the display still says it's playing the original track (Ghosts) though. The first second or two could easily be silent though. Once it's got into this 'confused' state, it will then continue playing the rest of the playlist whilst always displaying the previous song title. Pressing Play, RWD or FWD resets it. I'd assume therefore, that there's no checking in the code when it's playing the next song in a playlist, that the title agrees with the stream? The fast forward/rewind (2x, 4x etc) seems messed up too - is that related? BTW - I've gone back to FW55 because FW61 is so messed up - but it doesn't seem to make any difference to this.
Chris found a reproducible case in bug 4064, which has been fixed in change 9487. It will hopefully also fix this bug. Please test again with tonight's nightly, and d_source logging in case it's still broken. Please use firmware 61.
Unfortunately r9488 /FW61 doesn't fix it. I'll post a log when I get a chance.
OK, having got it to 'break' once, I've now enabled debug and I can't get it to break again ... so at the very least it's much, much better than before. I'll try again tomorrow and keep you posted. Thanks!
Great, do you see this error message in the debug now? Error: Decoder does not support file format, skipping track That would indicate your problem file is related to the bug I fixed.
Created attachment 1503 [details] log with d_source enabled
No I don't see that at all. There's definitely nothing wrong with the flac files - they play perfectly well at other times on the same Player, and it's not limited to any particular files. I have now managed to break it (although it does seem much harder). Playlist:- 1. 1. Nice To Know You by Incubus from Morning View 2. 2. Circles by Incubus from Morning View 3. 3. Wish You Were Here by Incubus from Morning View 4. 4. Just A Phase by Incubus from Morning View 5. 5. 11am by Incubus from Morning View 6. 6. Blood On The Ground by Incubus from Morning View 7. 7. Mexico by Incubus from Morning View 8. 8. Warning by Incubus from Morning View 9. 9. Echo by Incubus from Morning View 10. 10. Have You Ever by Incubus from Morning View 11. 11. Are You In by Incubus from Morning View 12. 12. Under My Umbrella by Incubus from Morning View 13. 13. Aqueous Transmission by Incubus from Morning View Player says it's playing 'Aqueous Transmission' but is not actually playing anything. This is not quite the same syptom as playing the wrong track, but I'm hoping the trace helps track something down. Log with d_source attached
FWIW, I notice the same behavior with SB2 and SS 6.3.1 FLAC and Win XP Pro. Choosing the song via the web interface corrects the problem.
Ross, could you give the SB2 player UI a workout (mostly using the remote, it looks like) to try to reproduce this?
It's much harder to break now that it was when I first reported this, but I've managed to capture a d_source trace:- Playlist:- 1. 1. The Changingman by Paul Weller from Stanley Road 2. 2. Porcelain Gods by Paul Weller from Stanley Road 3. 3. I Walk On Gilded Splinters by Paul Weller from Stanley Road 4. 4. You Do Something To Me by Paul Weller from Stanley Road 5. 5. Woodcutter's Son by Paul Weller from Stanley Road 6. 6. Time Passes ... by Paul Weller from Stanley Road 7. 7. Stanley Road by Paul Weller from Stanley Road 8. 8. Broken Stones by Paul Weller from Stanley Road 9. 9. Out Of The Sinking by Paul Weller from Stanley Road 10. 10. Pink On White Walls by Paul Weller from Stanley Road 11. 11. Whirlpools' End by Paul Weller from Stanley Road 12. 12. Wings Of Speed by Paul Weller from Stanley Road Reality:- It tells me it's playing 'The Changingman' but it's actually playing 'Porcelain Gods' Log attached
Created attachment 1517 [details] d_source logfile
Created attachment 1518 [details] continuation of logfile contination of logfile with d_source showing further 'end of file or error on socket' messages, and with song playing / now playing indicator continually out of step.
Andy do you have any thoughts on how we could "fake" that end of file error to try to repro?
'end of file or error on socket' is a normal message. EOF should occur on every track if played through to the end.
So what other flags or debug do you want me to run to try and track this down?
Not going to get fixed for 6.5.1. Leaving it open for 7.0.
(In reply to comment #28) > Not going to get fixed for 6.5.1. Leaving it open for 7.0. that's sad, because I think I can reproduce that bug quite easily: if a file cannot be opened, the player skips the file after some seconds and plays the next one. the display of 'now playing' however stays at the previous (not accessible) file.
Ross, could you spend some time looking at this to try to get some solid step-by-step repro instructions?
I'm able to reproduce this issue consistently (and it's killing me!) :) It affects a few of my favorite albums. Let me know what I can do to give the appropriate info for you guys. Thanks, Mike
A --d_source log showing the problem would be helpful.
Steven, could you spend some time today trying to come up with some good, step-by-step repro instructions for this? It seems clear at this point that it is never going to happen every time, but if you could get it to the point where it happens some known percentage of the time, that would be great.
I have not been able to reproduce the behavior yet but I am still trying. I am running firmware 72 on the box. Is anyone still able to reproduce the behavior with the nightly?
OK, I was able to reproduce the described behavior. Moving on to documenting the steps required.
Well, try as I might, I can't reproduce the behavior now.
(In reply to comment #36) > Well, try as I might, I can't reproduce the behavior now. > Steven, Please PM me. I can provide MP3 files, debug output - whatever you need. I can reproduce at any time. I have the latest official release (not the nightly). Would you suggest I upgrade to the nightly first? Thanks so much!, Mike mmonacella *at* gmail #dot# com
Mike, would you attach an archive of your mp3 files that produce the behavior here? I would like to see if I can reproduce the behavior with your files. When you say the latest official release is that 6.5.1?
I suspect the reason why you're finding this bug so difficult to reproduce, is because it only occurs when there is a file system problem. I think it occurs when SS tries to play a track that's in the library, correctly identified etc, etc, but for some reason, the file system won't give it the file (within a time limit?). At this point, SS moves on the play the next track, but never updates the currently playing variables, which puts it out of step. I suspect it's one of those problems that requires someone who knows the code to examine the logic and work out where it can go wrong - then add some code to make it (more) error resistant.
Steven - I'll work on getting you that archive. Thanks! Patrick - I'm not sure it would be a file system thing (directly OS-related at least) since (and maybe I'm in the minority here) the files seem to be play just fine through any other player (WinAmp, etc.).
Created attachment 1783 [details] Three AAC files - first two get skipped, third gets played Contains three files - first two files get skipped and third gets played using: SlimServer Version: 6.5.1 - 11206 - Windows XP - EN - cp1252 Firmware 72 Files otherwise work fine in any other player
Comment on attachment 1783 [details] Three AAC files - first two get skipped, third gets played Mike, thank you for the files. Turns out you were experiencing a different bug. These are actually AAC files not MP3. Turns out Slimserver has a problem with AAC files that are named with 64 characters or more. I created bug 4705 for this problem. The work around for now is to just use less then 64 characters for the file name.
Steve - thanks so much for your help in diagnosing it and offering the workaround!
Patrick, are you still seeing this?
I've just fixed bug 5103 and I believe it may have been the cause of this one too. Please test tonight's nightly!
I started to see this bug a lot at home, primarily with large playlists or random mix; after working for a few hours and skipping from time to time this bug would crop up. I updated to 6.5.4 nightly mid August and haven't seen the behavior again. Is anyone else seeing it after change 5103?
*** Bug 5946 has been marked as a duplicate of this bug. ***
This has been identified as a firmware problem, specifically related to FLAC
The issue here is that it can happen that the decoder is still running from the old track when data for the new track start to arrive in the buffer, already reading the FLAC header of the new track. Then when SC sends the start command for the new track the decoder already is past the FLAC header, reading on to try to find it. The result is that the data for the new track are consumed but no music is playing. I looked at the code and there is no easy fix for this + the risk is high to break something else. Therefore it has been decided that this bug will be fixed together with the redesign of the SC-side player state-machine.
*** Bug 5996 has been marked as a duplicate of this bug. ***
From bug 5996 notes: The following STMd frame is interesting. It shows that *both* the decode and output buffers are empty. The bytes_received value is correct (complete size of trailing track segment). Note that elapsed milliseconds is still 0 and no sound was heard. The STMd is not followed by any STMu. [08-04-17 08:20:53.5723] Slim::Networking::Slimproto::_stat_handler (722) 00:04:20:05:cb:14 Squeezebox stream status: event_code: STMd bytes_rec_H 0 bytes_rec_L 684227 fullness: 0 (0%) bufferSize 3145728 fullness 0 bytes_received 684227 signal_strength: 65535 jiffies: 248901594 [08-04-17 08:20:53.5727] Slim::Networking::Slimproto::_stat_handler (734) output size: 3528000 output fullness: 0 elapsed seconds: 0 [08-04-17 08:20:53.5730] Slim::Networking::Slimproto::_stat_handler (746) elapsed milliseconds: 0 server timestamp: 0 [08-04-17 08:20:53.5735] Slim::Player::Source::decoderUnderrun (599) 00:04:20:05:cb:14: Decoder underrun while this mode: playout-stop
*** Bug 11893 has been marked as a duplicate of this bug. ***
Targeting based on engineering discussion