Created attachment 998 [details]
Screenshot illustrating bug

in this screenshot, "Words of Wisdom" was playing for the entire duration of
the time "Antistar" was displayed.  In fact, I think it skipped directly to
"Tropicville" (and the display was correct) without playing "Antistar."

Created attachment 999 [details]
another screenshot, more detailed information

Before this screenshot was taken, we heard "Afro Blue" (four tracks up from the bold one).  Then we heard "Street Guru" (and took this screenshot, they were sync'd).  Then after "Street Guru" we heard "Out of My Hands", but the display said "Marlowe".  This three-song sequence and playlist jumbling took place without any input from the UI or the remote control.

Whoa!

Comment on attachment 999 [details]
another screenshot, more detailed information

Sorry, attachment 999 [details]'s description shhould say the following:

Before this screenshot was taken, we heard "Afro Blue" but saw  "Not Like the Other" in Now Playing. Then we heard "Street Guru" (and took this screenshot, while they were
sync'd).  Then after "Street Guru" we heard "Out of My Hands", but the display
said "Marlowe".  This three-song sequence and playlist jumbling took place
without any input from the UI or the remote control.

SlimServer Version: 6.2.0 - 4753 - Linux - EN - utf8

Happening with the released 6.2.0 version too.  At the moment my "Now Playing" shows a few songs ahead of what I'm hearing.

Will:  can you try to reproduce this issue with tonight's 6.2.1 nightly build?  There are a couple of fixes in there that shoudl address this problem.  If you can reproduce this, please reopen the bug.

SlimServer Version: 6.2.1 - 5157 - Linux - EN - utf8

I can no longer reproduce the bug with this version.  Fix confirmed in 6.2.1 nightly.

SlimServer Version: 6.2.1 - 5157 - Linux - EN - utf8

Nope, not fixed as of the build listed above, I spoke too soon.  Same thing is happening again.  There are two SB2's sync'd, and I have occasionally been deleting songs from the random playlist, so perhaps that's got something to do with it.

Subject: Re:  "Now Playing" out of sync with what's really playing

When you say "random playlist" do you mean the new Random Mix feature?

Yes.

*** Bug 2334 has been marked as a duplicate of this bug. ***

I added a d_source log of this problem to bug 2334. 
The display was 3 songs behing and the log mentioned a 'song queue' with 3 tracks in it (and this is while playing a playlist with 1000+ tracks).
Is that the problem?

*** Bug 2691 has been marked as a duplicate of this bug. ***

This is driving me nuts! Is a fix really expected in 6.2.2?

Thanks!

Created attachment 1101 [details]
d_source log showing the index slipping

This log shows a rproduceable case.  Here, it is a failing transcoded song.  You see first, the failure, then it moves to the next song.   This seems ok, but when it reports the now playing song, it mentioned index 23.  23 is the failed song.  and it is playing the next song.  Pressing skip fwd, the log goes to the same song you see opened before, but now reports song 24 in the queue.  track start event missing from the failed transcode would seem to be the problem  I guess we need to update the queue maually on an error like this.

https://bugs-archive.lyrion.org/show_bug.cgi?id=2933

I have this problem but I am playing native FLAC and it seams to happen as a result of browsing RSS feeds or browsing the album list.

when browsing, how are you returning to the now playing track?  via the now playing button, or navigating back through the home menu?

I can reproduce this problem fairly consistently.

1. Start with 2 SB3s turned on and synchronized but not playing anything.
2. Select play random song.
3. Once the first track has started playing, turn off one of the SBs.
4. After several seconds, the SB that's still on will abrubtly end the current song (I'm guessing it's just playing out what's in the buffer).
4. The 2nd track will start playing, but the display will still show the 1st track.

Server version: 6.2.2 - 5924 

so, common thread here seems to be an aborted playback at some point.  dropping a player from a sync group shouldn't be causing the other player to drop the song, so it might be useful to have a d_source log attached that shows the activity at this point.  If some log items line up, it might help to  lock down the best point to fix this.  

> so, common thread here seems to be an aborted playback at some point. 

I'm not sure that's the case. I synchronised an SB3 player with an already playing S2 earlier today. I got the expected track restart (I understand that's WAD so I'm not complaining!) but by track 2 SLimserver was displaying the wrong track name (as, of course, were the 2 SBs).

I know I've mentioned this on the list a couple of times but how can Slimscrobbler get it right if Slimserver is wrong?

I'm not using synch, and playback does not stop for me.

However what's on the screen sometimes does not reflect what's actually playing, i.e. it's still displaying the last song while playback has moved on to the next song.

I'll turn on logging and submit my log when it happens again.

Thank Mark.  To keep the log cip manageable, try to centre is atound not just the point where you notice the song is wrong, but catch the openNext messages, and if you can spot it, the place where the song queue number first shows the incorrect index (first song in playlist in queue index 0)

Created attachment 1137 [details]
Mark Lanctot's d_source log

Now this may not be the best test case because something weird happened and I corrected it.

Playback suddenly stopped for no reason, so I pressed PLAY again.  It played one song, then moved on to another one...but the display did not update.

Then to be sure something was wrong I selected the first track again.

So this may have screwed up the log a bit, and since I don't know how to read the logs and found the instructions kind of confusing, I posted the log around this time centred around the tracks affected.

I wish I was listening to more dignified music at the time <blush> but the B-Boys are always fun to listen to.  :-)

I have a SB3 / Slimserver 6.2.1 that has similar symptoms.  In our case, the display on the SB3 and the web interface lags *behind* what is currently playing.  (it shows the song that played 1 or 2 songs ago, the delay grows gradually with time, it's been as much as 6 songs behind)

We don't have any players synchronised.   We recently reinstalled the Slimserver (OS reinstall - WinXPhome)

I'm not sure whether this helps or not but, in my case, I'm as certain as I can be that this bug relates to load on the PC running SlimServer. It's been fine for ages but this morning I started moving big files around and am also running Moose. It didn't take long for the Squeezeboxes to start displaying the wrong details. Interestingly we noticed that it is flashing up the correct details then changing them to the wrong ones (which perhaps explains how SlimScrobbler is able to log the correct details with Last.FM).

The play list currently bears no relation to what has or is actually playing and it is the play list track details that are being displayed.

Which debugging option will help debug this? I thought it was d-source but the log output from that is showing the corect track details.

I'm not sure that Kevin's problem above is not the same bug.
I got this problem without any loading on the SlimServer host and I have never seen the correct details shown then replaced with incorrect as described.

However I'm not running 6.2 any longer and have yet to see this particular problem in 6.5.

chris: can you reproduce this?

Not exactly.  I got the squeezeboxes set up for synchronized play, and hit fast forward several times without seeing a problem, but I re-read the bug and saw that it happened with shuffle play.  The instant I hit shuffle songs, my players started displaying an apparently random title while continuing to play the song that I'd started beforehand.

However, once that song finished, the displays began showing the correct title.

I tried to increase the load on my pc; difficult due to this nice new machine you got for me.

After that, I noticed on one occasion that my playlist had inexplicably stopped playing.

But for the most part, Slimserver appeared to be staggering onwards delivering my music.

A possibly-related bug that I was able to reproduce is this:

1) Set up a system with two Squeezeboxes synchronized.  I used one wireless and one wired, because that's what I ha on hand.

2) On the Slimserver browser page, start a playlist, in shuffle by song mode.

3) Hit FWD a few times to get down 4 tracks or so

4) Then delete a track from ABOVE the current song.

5) NOTE the display in the browser and the connected squeezeboxes now lists the track BELOW the currently playing track.  However, after the current track finishes, my system always recovers to displaying the correct information.

Also note, this DOES NOT HAPPEN with only one Squeezebox connected although I tried assiduously.  It does happen regardless of the load on the PC.

Have you tried turning one of the SBs off while synchronized and playing random songs? That usually causes problems for me.

Created attachment 1167 [details]
Tim Fletcher d_source w/notations

To be clear, Tim, I definitely BELIEVE you. :)

My task here is to find and document a way to reproduce the problem so that Dan can think clearly about it and implement a fix.  I appreciate the information, and I'll keep at it.  In the meantime, I found something (see above notes) that maybe Dan will have more luck reproducing that MIGHT have the same root cause.

This is a real problem, and it really needs fixing, but we don't need to stop the 6.2.2 release for it.

Dan, as I mentioned in the comments, I couldn't reproduce this exact symptom, but could you look at the problems I did see?  With any luck, the root cause will be the same.

looks like bug 3336 may be a reproduceable case of this problem.  involves sync and changing shuffle modes.

I believe there actually two bugs related to the problems described here (maybe more:). One where the display is off by one track, and one where the display is seemingly random. This bug seems more focused on the first issue, so I've created a second bug #3389. I think some of the descriptions here might be people experiencing that bug.

This bug does not seem to be tied to random, it happens when you play a single CD as well. It seems like it's strictly related to synchronization. It seems to only happen when a synced player is un-synced or turned off. In fact turning a synced player on seems to re-sync the tracks.

It may be related to #3336, but that bug report says it synchs up on the next track. The problem I experience never synchs back up. It stays consistently one track off. Skipping forward or back one track sometimes re-syncs, but not always. However if you just let it play it will always be out of sync.

agree with all that Tim's just put, except I *never* synch players and I used to get this quite frequently.
Yet to see this problem in 6.5 however.

I also never synch players, and it happens to me fairly regularly.

It's also sometimes not off by one track, but sticks with a certain track.  New tracks play just fine but the track index stays the same.  The progress bar is interesting - it's sized for the track that's displayed yet is accurate for the track being played - so, for example, the track can end before the bar is filled or the time index can go on for some time after the bar is full.

I also notice it doesn't happen very often with Random Mix.

My workaround now when I notice this happening is to skip to the next track (the one currently playing) which restarts playback with an accurate display.

I'm sorry I don't have any other logs to post right now.  I'll keep them on but I'm not sure what I'm looking for, i.e. which snippet to post.  I'll just include everything around the time the issue first starts.

There really is NO need to keep creating bugs for different cases of the same problem.  They are still likely the same root cause, and you just make it harder to keep track of all the info.  thanks.

Dan I have left two SB3s on your desk for next time you are in the office, if you'd like to use them in looking at this problem.

I've checked in a fix for bug 3336, can someone try reproducing this bug with 6.3 r7840 or higher?  Also please include --d_sync and --d_playlist in your log file if you can reproduce.

For those testing, I've checked in another fix that appears to solve Chris's "delete song above current song" bug described in comment #27.

Few more sync fixes checked in today.  Would really be interested in finding out how to reproduce this bug. :)

I can no longer reproduce the issue I reported.

If anyone else is still having problems, I need to know so we can get this fixed for 6.3!

Thanks.

I'm still having the same problem. I'll try to post some debugs tomorrow.

SlimServer Version: 6.3.0 - 7895 - Linux - EN - utf8 

Created attachment 1263 [details]
log with d_playlist and d_sync turned on

Ah ok now we might be getting somewhere.  I can't duplicate the incorrect Now Playing text on either 2 SoftSqueeze's or 2 SB's, but there is something that goes wrong when you turn off the first player.  The other player will lose its progress bar and skip to the second track in the playlist after about 30 seconds.  After this skip to the next song, everything is normal.

Can you re-run your log with d_source included in addition to d_sync and d_playlist?  Have you tested with real SB's or are you just using 2 SoftSqueeze's?

I've checked in a fix for the issue I saw, please test.

Oh by the way, I am only testing with 6.3, hope you are too.

I am currently running 6.3 (SlimServer Version: 6.3.0 - 7895 - Linux - EN - utf8).

I usually use 2 SBs. When I was capturing these logs this morning was the first time I've even tested this issue with SoftSqueeze. It doesn't seem to make any difference.

On the positive side, I'm no longer seeing the symptoms described in bug 3389, so it look like something you did fixed that.

I'll try to post another log with all the debugs soon.

If it would help, I can give you ssh access to my system and you can see what happens for yourself.

Please update to r8002 or higher when testing.

I'm also seeing this - but wanted to add some additional details in case they're helpful. I think this is all the same problem - but apoligies if I'm seeing two unrelated bugs.

I'm running 6.3 7337 - I know it's old and will update and check with the latest build.

I also think this connected with server load - but what is interesting is that what goes wrong is more than just the web displayed track getting out of step. Once the track has become out of step I also see:-

1.) The volume, pause and stop controls on the web interface stop affecting the SB2 - or at least they work a long time later - typically at the end of the track.

2.) The SB2 remote also stops working - although the music keeps playing

3.) Once the current track ends the SB2 comes back - although the web interface doesn't get back into step.

Hope this is helpful -please ignore if it isn't.

I'll confirm this is the same on the latest build in a day or two.

I also noticed some of the behavior Greg mentioned, but so far I have not been able to reproduce this in r8002. I think you've got it! Could you let us know when these patches get integrated into 6.5?

6.5 should have all the same fixes.

Thanks Andy. I've tested the latest 6.5 nightly and it seems to be working fine.

(In reply to comment #51)
> I also noticed some of the behavior Greg mentioned, but so far I have not been
> able to reproduce this in r8002. I think you've got it! Could you let us know
> when these patches get integrated into 6.5?

Same story - I can no longer reproduce this in 8020 -great news guys - thanks!

Marking fixed.

This bug fix is now part of a released version, and so has been marked closed. If you are still experiencing this problem, please reopen the bug.

It's baaack. I don't when it started, but I'm having this problem again.
1. Sync 2 SBs.
2. Turn 1 off.
When the SB that's still playing advances to the next track, the display does not advance, and stays one song behind. Hitting the FWD button on the remote corrects the problem. I've tried several recent nightlies, but they all see to have this problem. Currently using 10992.

So how do I get this re-opened.

Please re-open this bug. I encounter this problem with regularity. I'm running SS 6.5.2.

You realize 6.5.2 is 3 versions out of date?  Please run the latest SC7 nightly build.

I am running 7.2.1 nightly 23565 (October 17, 2008).

This is what happened to me on October 23: I have a SqueezeBox 2 playing in Random Mix (random songs) mode.  I had the SqueezeCenter web interface loaded in Firefox on my Windows box.  SqueezeCenter runs on my Linux box.  I looked up at the web interface, and Now Playing was showing the previous song played, but the elapsed time bar was moving.  I looked at the SqueezeBox, and it was also displaying the previous song, with a live elapsed time bar, showing it as "now
playing".

When the next song came up, the display on both the SqueezeBox and the web interface was off by one song.  When I skipped a track forward with the web
interface, it was still one song off.  When I turned the SqueezeBox off, and
back on, it was still one song off.  When I scrolled to the next song in the
"Now Playing" list and pressed play, it played the song displayed, and the "Now
Playing" display showed the correct song on both the SqueezeBox and the web
interface.


Please tell us:
1) what content you are streaming

FLAC files resident on the server running SqueezeCenter

2) what screen saver you have enabled on the controller

Now Playing screen saver

3) does this happen if the controller is docked (in charger) our out

I don't have a controller.

4) does this happen on SqueezeCenter ONLY, or also on SqueezeNetwork (please test on SN to see if you have the same issue)

This is the first time I have seen it in several days of use.  I don't really
have anything I want to play on SqueezeNetwork.  I can try it on Pandora, but
it looks like Pandora only has a single-element playlist.

5) please describe any steps you take to reproduce this issue so we can figure
it out here :)

I don't know how to reproduce it.  I wasn't taking any action at all when it
occurred.

These are the only error messages logged during the period when the problem
could have occurred:

[08-10-23 22:45:42.5907] Slim::Utils::Misc::msg (1398) Warning: [22:45:42.5903] Argument "" isn't numeric in numeric gt (>) at /usr/local/src/Audio/squeezecente
r-7.2.1-23565/HTML/Default/pageheader.html line 114.
[08-10-23 22:46:00.9873] Slim::Utils::Misc::msg (1398) Warning: [22:46:00.9868] Argument "" isn't numeric in numeric gt (>) at /usr/local/src/Audio/squeezecenter-7.2.1-23565/HTML/Default/pageheader.html line 114.

This is happening again on Version: 7.5.3 - r31792 @ Mon Jan 24 07:32:03 PST 2011. 'Now Playing' is showing the track one behind what's actually playing. This is on random play with several sync'd Classics and I've seen the problem three times so far.