Sounds similar to bug 4019.

It does sound similar to bug 4019 but this one only seems to occur when the players are synced.  I have also been able to reproduce on Mac OS X.

d_source logging may help identify where things are going awry.

After spending a lot of time 'playing' with this I can report that on my system it is caused by remote control software on a remote machine. I deleted and reinstalled Slimserver and started adding plug-ins etc. one at a time. 

The data displayed by the Squeezeboxes was correct until I started Moose (on a machine remote from Slimserver). When I came back a few hours later the display was out of sync as originally reported. FF seems to resolve it so I killed Moose, pressed the FF button and the display was fine for a few hours. I then started Slimremote and within a few minutes the display was wrong again. I killed Slimremote, pressed FF and it's been fine again for several hours.

If I press FF to correct the displayed data but leave either Moose or Slimremote running the display drifts again.

...and as a final test I left the Slimserver web page running on the same remote PC and that had exactly the same effect - within a few hours the Squeezebox display was wrong.

Kevin, thanks for the additional information.  However I was able to reproduce this on a clean system without any additional plugins or programs running to my knowledge.  The time it took for the behavior to appear could be a few minutes to a few hours.  I am still trying to produce a log that may show what happens when the now playing information gets out of sync.

Created attachment 2105 [details]
d_source log of now playing display out of sync of music.

This log was created while two SB3s were synced and playing a 'Random Mix'.  The random mix was set to show 5 upcoming songs and 5 recently played songs.  While 'Pearls' was about half way through playing the now playing display switched to the next song. 'Pearls' however continued to play normally and in sync.  From that point forward the now playing display was ahead of the audio and the time display was wrong or showed zero.  The other thing that I noticed is that 'Random Mix' stopped adding tracks after the 'Pearls' event occurred.

SlimServer Version: 6.5.4 - 12558 - Windows Vista - EN - cp1252

I've just checked in a large patch to the SlimServer 7 sync code, thanks to Alan Young.  Please retest this issue.

Steven reports this still appears to be broken.

I'm not sure whether the comment by Chris refers to v7. I suspect it does but, just in case, I can confirm that the v7 build from 12th October exhibits exactly the same behaviour. I completely removed SqueezeCentre from my machine so I was starting with a brand new build with no plug-ins but it didn't make any difference - the displays were out of sync in quite a short while.

Audio synchronisation seemed to be perfect but couple this issue with the fact that random song play (which I use 95% of the time) is also screwed with synchronised Squeezeboxes and synchronisation is no good at all for me unfortunately :(.

Chris, I think the severity of this bug should be increased especially with the ability of SqueezeCenter 7 to synchronize playback of more sources then before.  What do you think?

I agree

Wait why is this assigned to me?  Setting to unassigned so we can review it in the next meeting.

Alan, isn't this fixed?

I don't know. I have not yet tested with any remote track-by-track streams. I'll look at it.

Dean, I'm afraid this issue isn't fixed. I loaded the 26th October nightly on my system yesterday afternoon and sync'd two Squeezeboxes - a 2 and a 3. This morning both boxes are showing the wrong track and time details. Kevin (waiting to see if synchronising the two boxes still screws up random play)

Kevin, Were they also playing random mix? Alan.

Hi Alan, yes they were.

It would be really helpful if you could recreate it with a logging enabled: 'player.source' at level debug and 'player.sync' at level info. Do you think that you woudl be able to do that? I have some clues from Steven's trace but not enough.

(In reply to comment #7)
Steve, is there any chance that you were testing with debug/pre-release firmware 82 wen you created your trace?

Kevin, Steven, I think that I have finally worked out what is going on. I don't need any more traces. Alan.

I just wanted to make clear that I have seen this happen a number of times without using random mix.  Random mix just seems to have the ability to make it happen quicker then not using random mix.  Change of more metadata between tracks perhaps?  Don't recall about the firmware.  I have more logs at home if you need them.  Oh wait, you said you did not need any more.

Should be fixed by change 14550. It would be great if you could retest.
Should also be the case that the next firmware (which reduced the incidence of sprurious STMo events) would also fix it in most cases.

I've been running the 11 Oct release for nearly 24 hours and the display is much, much better but not quite fixed. 

What appears to happen is that occasionally (sorry I can't be more precise than that) the Squeezebox will display track information for the next track rather than the currently playing track. When that happens the next track is skipped, i.e. it doesn't actually play at all, and, so far, the data for the following track is displayed correctly. 

I've tried this with the LastFm/Squeezescrobbler plug-in both enabled and disabled and it doesn't seem to make any difference. When the plug-in is enabled the correct data for the now playing track is scrobbled even if the Squeezebox is displaying the data for the next track.

I'm not sure this makes sense so I'll try to illustrate it:-

We have tracks 1, 2, and 3 which are scheduled to be played consecutively in the random song play playlist. In the scenario where the Squeezebox is displaying incorrect track information and track 1 is playing, the Squeezebox (and web interface and Moose) will display the track data for track 2 although the progress bar seems to accurately follow the track's progress. If the LastFM/Squeezescrobbler plug-in is enabled it will scrobble the details for track 1. When track 1 completes track 3 will start and, IME so far, the data displayed will be correct. 

This is a significant improvement on what was happening before, thank you. 

(I thought it would be a bit presumptuous of me to change the status of the bug but I don;t think it's quite resolved)

Kevin, you say you are running the 11 Oct version but I only checked in the change on 09 Nov. Perhaps you meant 11 Nov. If you can recreate it with player.source logging at level debug, and player.sync at level info then that would help in tracking it down. Alan.

Sorry, I'm in a time warp, I meant 11th November. I'll have to wade through the Help to figure out how I do the debug logging so there will be a short delay.

Created attachment 2401 [details]
Log created during erroneous Squeezebox display

I'm not sure whether this is going to help as I can't see anything in the log that bears out what actually happened but then as this is the first log I've ever looked at that may just be ignorance talking!

'Incubus' by Marillion was playing and being displayed correctly. 'Ride a White Swan' by T.Rex started playing and was being displayed correctly. Partway through the track the display data changed to 'Thank You For the Music' by Abba which was the next track in the playlist according to the Squeezecenter web page  (first time I've noticed that the track data displays correctly at the start and changes partway through the track).

'Ride a White Swan' finished then 'Let's Get Metaphysicial' by David Gilmour started, i.e. the Abba track did not play, and the display was correct.

Created attachment 2402 [details]
Squeezecentre log while Sqzbox display wrong (no Squeezescrobbler)

I noticed that when I disable Squeezescrobbler it still seems to do most of its work and just omits the send to LastFM. I removed the plug-in then restarted Squeezecentre. I fast forwarded a few times just to get things ging and seemed to upset the display somewhat.

The first track I allowed to play was 'Little Children' by Billy J Kramer. The Sqzbox was displaying track details for a Queen track that was 2 further on in the playlist.

That track finished, the next two tracks were skipped by the system and 'Blood Brothers' by Iron Maiden started. Once again the details displayed on the Sqzbox were those of the track 2 further down in the play list.

That track finished, the next 2 tracks were skipped by the system and 'Shakedown Street' by The Grateful Dead started. The displayed track details were correct.

'Midnight Blue' by Lou Gramm then started. The track details displayed on the Sqzbox were those of the next track by Queen. I noticed that while the progress bar on the Sqzbox were correct for the track actually being played, the bar on he web interface was incorrect.

This track finished, the Queen tracked was skipped and 'The Calling' by Fates Warning started with correct track details being displayed. I then copied the attached log which shows everything logged from when I restarted Squeezecenter to the start of the Fates Warning track.

Thanks for the logs. I'm sorry to say that I cannot see what could be going wrong from that trace. The play control now appears to be in order. There must be something else which is messing with the playlist and now-playing displays. Can you try adding 'plugin.randomplay' at debug level and 'player.playlist' also at debug level?

Created attachment 2407 [details]
New Log  as requested

This is going to be rather a long report, sorry, and I think the best way to 
explain what is happening is to document the part of the playlist played during the creation of the log and what happened with each track (note the playlist is being created by Random Song Mix).

1. Network News - Robert Plant: Played, Display OK
2. Call Me - Blondie: Played, Display track 4
3. Daughter - Pearl Jam: Skipped
4. Maps and Legends - REM: Skipped
5. Dream Evil - Dio: Played, Display track 6
6. Candles Burning Blue - Rick Richards: Skipped
7. Real Love - David Gray: Played, Display track 8
8. Tomorrow - Edguy: Skipped
9. Half-Light - Porcupine Tree: Played, Display track 10
10. Yesterday's Dreams - The Four Tops: Skipped
11. Mighty Wings - Cheap Trick: Played, Display track 12
12. Aliens Exist - blink182: Skipped
13. Born to End - Manic Street Preachers: Played, Display OK *1
14. Magnum Opus (Live) - Kansas: Played, Display OK
15. Runaround - Van Halen: Played, Display OK *2
16. Pushing Me Away - Linkin Park: Played, Display track 18
17. Sweet Jesus - Barclay James Harvest: Skipped
18. Can't Slow Down - Joe Satriani: Skipped

I wanted to wait until display and track coincided so we started the log 
from a known good point and it was being a particular PITA today with 
the track not matching the display most of the time. Anyway, it did eventually display the correct information so I saved the new log requirements and created the attached.

I was watching the Squeezecenter web page in Firefox on a remote machine while the log was being created. At *1 the web display stopped being updated which coincided with the Squeezebox/Web display being correct. It stayed correct for the next three tracks then went awry again at *2 shortly after I'd hit the refresh button which meant the web page was live again. I suspect this is coincidental as I don't have the web page showing at the moment but the Squeezebox display is still wrong.

FYI I'm running Squeezecenter on XPP SP2 on a Laptop with a Pentium M processor (probably 1.4GHz) and 512Mb memory. Processor utilisation doesn't seem to run much above 14% but I am seeing memory spikes every time a new track is loaded; I'm not sure whether that is going to be an issue or not. 

Kevin

> Processor utilisation doesn't seem to run much above 14% but I am seeing memory spikes every time a new track is loaded;
> I'm not sure whether that is going to be an issue or not. 

I think you can safely ignore this. I've just increased the memory to 1Gb and I see the same spike.

Kevin, I think that I have an idea of what is going on now. Several different issues.

Thanks for the traces. They were a big help.

I think that I have uncovered three issues relevant to what you see.

1. The biggest problem is that the code which handles a track start event (newsong) in the RandomPlay plugin will first delete the oldest song from the playlist, before adding a new random song to the end of the playlist. If the track start event comes from a slave player (sync-groups have a master and one or more slaves, although that it not really obvious anywhere in the UIs) then code which handles adjusting the current playing song's position in the playlist (moving it from 6 down to 5, for example) then the adjustment fails. The system will think that it is playing song 6 when it is actually playing song 5.

2. The above is made worse by the fact that it can be repeated for multiple slave players.

3. The above is made even worse because sometimes (quite often) multiple track start events get issued by a player for the same song. I have entered bug 6156 for this.

The combined effect of these is that: (a) the now-showing display can be wrong, and (b) tracks can get skipped over (not played). Just to add to the fun, a track that actually gets displayed as now playing may never get played.

I think that I have fixes for the first two of these. With these in place, then the impact of the third is likely to be minor.

> I think that I have fixes for the first two of these.

Excellent, I really appreciate your efforts on this and am more than happy to give it another test when the time comes. It always puzzles me that there's not more clamour when sync doesn't work correctly. As I've said before, I use that and random play most of the time (and it was the primary reason for my purchases) but I assume I must be in a minority. Kevin

I've just checked in change 14714 and change 14715 for the first two problems. Kevin, Please try with these. I think that, although these bugs are actually more general, they only really hit when sync and random-play are combined.

If you think these changes have fixed the issue, shall I mark it 'Fixed'?  That's our usual process, with a directive to re-open if there's still a problem.  Thanks, Alan!

Chris, given that I have had to reopen this once already, after my first fix was insufficient, lets give Kevin a couple of days to test it again in his environment.

No problemo.

I've just installed the 15th November release assuming the fixes are in there so I'll let you know how it goes ASAP. Kevin

It's probably too early to say yet but, just to give you an interim update, I've seen no display issues on my Squeezeboxes at all since loading the 15th Nov build and I would have expected to see loads of them by now with the previous release. I'll give it another 24 hours then report back again but it's looking good so far, thank you. Kevin (you've no idea how pleased I am about this so I hope I'm not tempting fate!)

I think you have it Andy. It doesn't seem to have missed a beat since yesterday and I tried to upset it this morning by FF over several tracks and restarting tracks but it's been spot on. Thank you. Kevin (I'm probably going to upset it now by introducing Softsqueeze if I can figure out how to install the test version!)

Good. Thanks for testing it. I'll mark it as fixed (for the second time). Alan.

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.