Created attachment 391 [details]
debug log capturing the behavior

I'm having the same problem as the original poster. In my case, it's 
happening on a SB2 with 6.0. It's stopping at the end of FLAC tracks. I also 
have an SB1 connected to the same server, but the two devices are not 
synced.

I've attached a d_source log. I believe that what I saw happen was as 
follows:

SB1: Manually paused in the middle of playing the album O Brother Where Art 
Thou for at least an hour.
SB2: Playing Diana Krall

SB2: Hits the end of the song Temptation and stops.
SB1: Wakes up and begins playing the next track on O Brother Where Art Thou. 
SB2 remains stopped.

is this happening with a particular skin?  I'm not seeing the same thing here,
but I always use fishbone.  The reason I ask is that most skins refresh on a
track boundary, and we have seen problems before where the url in the refresh
can somehow get locked into a command or player.

I'm also using Fishbone. I'm not convinced, though, that I've always had a UI 
up when the problem has occured (I run SS as a service on a headless system).

Actually, pause doesnt seem to restart - I find i need to skip to another track
and then back to get it to play.

I have put one of my SB1's on pause.  I have an SB2 playing tracks for 5 hours
now with no pause on SB2 and no unpause on the SB1.  Pressing pause on the
remote for the SB1 starts playback from the point it was paused 5 hours before.
 The SB2 hasn't been playing FLAC tracks, but have switched to that now.  SB1 is
paused mid-flac track.  This is using the latest nightly build.  That would be
worth a try if you have no already tried it.

This is a slimserver bug, moving to that product.

I'm also seeing the bug with Softsqueeze.  At the end of a track I need to press
next track for the next track to play.  Sometimes it reports that the next track
is playing, and it even reports the time left of the next track without any
audio.   More frequently however the track playing will just halt at the end and
the "next" button will have to be clicked before the next track will play.  This
was happening with 6.0 and 6.01.  I'm running Fedora Core 3, Slimserver 6.01,
and SoftSqueeze 2.0b5.

I will again state that I have not seen this with april 02.  It would be
(hopefully) useful to see d_source logs from someone using the latest NIGHTLY
BUILD. 

Created attachment 452 [details]
Log with Vidur's patch installed

This is a log of the multi-player synchronization problem with Vidur's patch
installed.

Two players are involved: "Family Room" and "Office".

Sequence of events is as follows:

1. Begin playing Diana Krall album on Family Room
2. Begin playing O'Brother Where Art Thou on Office
3. First song (Stop This World) completes on Family Room - player does not
advance to the next song. This occurs in the log at 7.33.05.XXXX.
4. First song (Po Lazarus) completes on Office. Both Office and Family Room
advance to the next song. This occurs in the log at 7.34.37.XXXX.

I stopped the log at this point. The behavior remains the same throughout the
rest of the album on Family Room - it stops at the end of each track and does
not progress until Office reaches the end of its current track.

Created attachment 454 [details]
Log showing problem with latest (2005-4-23) nightly

I've attached a log showing the problem from the latest nightly (6.0.2 4-23). I
didn't specifically apply Vidur's patch as it appeared that his changes were
already in the nightly build version. 

The test setup is exactly as before (see my forum post), the "pause" is between
22:50 and 22:56 (the SB1 continued playing as normal, the SB2 waited for the
next transition on the SB1).

Hmm...neither of the new logs includes any of the new debug messages (a line
including the phrase "pending chunks"). I'm not sure how that's possible with
the patch applied or a recent nightly build - all codepaths following the line
starting with "playing out before starting next song..." lead to one of the new
messages.

Greg, I presume that you're using slimserver.pl and not slim.exe (if you're on
Windows), after you applied the patch? Or if you're using an nightly please
confirm that it's 4/22 or later.

I plead ignorance on Slim.pl vs. Slim.exe. I'm running 6.01 release as a 
service on W2k3. After hand-patching the affected files, I bounced the service 
(net stop slimserver, net start slimserver).

So how do I run slim.pl? Is it as simple as stopping the service and running 
slim.pl from the command line? Instructions or a pointer to instructions would 
be appreciated, and I'll give it another go tonight.

Hey Greg, I know this ...

First, be sure that ActiveState PERL is installed on your Windows system.

Then, stop the service, CD to your slimserver installation directory in a 
command window, and type:

<path-to-activestate-perl>\perl.exe server\slimserver.pl

That'll do it ...

Oh, one more thing:

Be aware that if you patch a SlimServer source on Windows, but are running 
the .EXE file, the PERL files are never used.  The .EXE file (which you'd be 
running as a service) contains the interpreter, and the perl files aren't 
actually used in that context.

You MUST run via PERL (not the .EXE) to have the perl files used ...

So, basically, due to your methods (stop/start the service), you ran the 
identical code both times.

Let me know if you have further questions.  Give me a call tonight (get my # 
from Nigel) if you have any problems ...

Thanks, guys.

Jeff - From Vidur's comments, I figured that Slim.exe wasn't picking up 
changes to local perl files. I'll give it a whirl tonight and give you a call 
if I have problems. Thanks!

Is it possible that the windows exe also isn't built from the latest source?
(seems unlikely to me). As I mentioned, I was running latest nightly, and the
source files had the extra debug messages, but none came out. If I get a chance
I'll install activestate on my server and try that, seems a bit weird though.

Created attachment 457 [details]
Log w/"No pending chunks" traces

This captures the behavior with Vidur's traces.

Scenario (and the specific albums/tracks involved) are the same as in my
previous post.

Created attachment 458 [details]
log with 6.0.2 4-25

OK, so I upgraded again to the latest nightly. This time the debug messages
seem to be appearing, hope this is more useful.

I know I'm being a pain about this, but remote debugging is hard (radish, I
think you suggested at one time that I could Remote Desktop to your machine?).
In either case, could you turn on --d_http as well for the problem and post a
log? Thanks.

The Remote Desktop offer was for another bug. Sorry.

Hi,

I just wanted to lend any support I can to this bug. I am seeing exactly the 
same thing. It always happens at track boundaries. Sometimes pause and play 
works, sometimes I need to select the next track to "unpause" playback. 

If it helps at all I'm not seeing this bug: http://forums.slimdevices.com/
showthread.php?t=13726&page=2&pp=10 and the vast majority of my collection is in 
FLAC. 

I'm using a recent nightly build: 6.1.0 - 2895

Please let me know if there is anything I can do to help with fixing this one.

Chris.

Created attachment 464 [details]
log with http trace as well as source

Vidur - as requested a log with http enabled as well as source. Setup otherwise
exactly as before.

Looks like the last log was just --d_http. I don't see the --d_source. :-(

FYI - we're under external pressure to get 6.0.2 out, but I'll continue treating
this bug as a high priority. Not to worry, once we get a fix, I'll get it into a
stable build soon.

Created attachment 466 [details]
second go with http & source

Sorry - I got in a tangle with starting & restarting the server last night.
Here's another attempt. I checked this one and it looks like it has both sets
of messages to me.

Created attachment 467 [details]
Log with source & http

Another log of my repro in case it adds value to Radish's.

Same albums, same scenario as before. Generated by the release drop of 6.01
with Vidur's changes applied.

OK. I finally was able to recreate this problem and I'm stumped so far. Here's
what I know:

1) SlimServer closes the streaming socket to the SB2 as expected. This does not
result in a FIN/RST TCP packet as one would expect. The socket remains in the
ESTABLISHED state according to netstat. Somewhere between our call to close() at
the Perl level and the TCP implementation, the close seems to get lost.

2) This only happens on Windows. I couldn't recreate on OS X. I don't know if
this is a function of the Perl implementation or the OS.

3) This only happens if the track playing on the SB1 is being transcoded to PCM.
I can't recreate if the non-FLAC track is MP3.

4) This only happens if the track on the SB1 starts after the track on the SB2.

I'll continue to investigate...

Created attachment 468 [details]
proposed fix

I've attached a possible fix. It seems that either Perl or Windows may be
putting the socket in a state that delays closing. Could you guys apply and let
me know if you see an improvement?

I just patched my server and retried the same test case I've been using all
along - looks good now! Any idea when this can be rolled into an exe bundle so I
can run it as a service?

Thanks for your help on this Vidur, much appreciated. Now if only someone could
fix 1434 I'd be totally happy with my flac rips ;)

I can confirm that your patch fixes the problem. 

An alternative to setting SO_DONTLINGER is to call 

$httpClient->shutdown(2);

immediately before the call to close. Setting SO_DONTLINGER before calling 
close will cause any unsent data in the send buffer to be dropped on the 
floor. Calling shutdown will allow data in the send buffer to get sent and 
should guarantee that a FIN is sent after the buffer is drained.

I tested with the call to shutdown, and it works on my system. It's probably 
not a bad idea to call it on all platforms, but you probably know the 
idiosyncracies of the various socket implementations better than I do.

MSDN docs on shutdown are at the following link and should apply if Perl's 
socket APIs are a shim:

http://msdn.microsoft.com/library/default.asp?url=/library/en-
us/winsock/winsock/shutdown_2.asp

Thanks for debugging this!

I was under the impression that SO_DONTLINGER did a graceful shutdown and that
SO_LINGER with a timeout of 0 threw away remaining data...but I'm seeing
problems with the web interface with the SO_DONTLINGER patch. Thanks for the tip
about shutdown, Greg. I'll investigate and post a new patch.

Created attachment 473 [details]
patch with shutdown

It seems that shutdown() is definitely a better option (thanks again, Greg).
I'll get this patch into the 6.1 trunk and 6.0.x branch. We haven't yet decided
whether to do a 6.0.3, but the nightly 6.0.x build is still available. Check
http://www.slimdevices.com/downloads/nightly/latest/6.0.3/ in the next 24
hours.

The patch is pretty conservative about using shutdown(). I'm still a little
wary, given potential differences between Windows and other platforms (see
http://www.experts-exchange.com/Programming/Programming_Platforms/Q_20341636.html,
for example). But, with a little more testing, we can consider the shutdown()
on other platforms and non-streaming connections.

Fix checked into trunk (change 3104) and 6.0.x branch (3105).

I'll wait for the next nightly and give it a try.

Thanks again.