7.4 breaks SqueezeSlave for me, too.

Using a similar setup: Vortexbox, 7.4, squeezeslave 9.84 fedora 11.

SqueezeSlave worked OK on 7.3x, broken with 7.4.  Updated SqueezeSlave to recently compiled 9.84; still broken.

Switching from Internet Radio to local Flac files, kills SqueezeSlave.  Have to reboot to get SqueezeSlave back.  Other physical SqueezeBox devices, like SB3, play OK even after SqueezeSlave dies.

Hi,

Here is a whole thread about the problem.

http://forums.slimdevices.com/showthread.php?t=69338

Squeezeslave 0.9-95 is still broken

Same here on both Vortexbox (Fedora) and Ubuntu builds, using a Duet Controller to control squeezeslave.

7.3 Worked perfectly in both instances.

This is a bug with squeezeslave which has not kept up with changes to the server.  Needs to be assigned to the squeezeslave maintainer.

If you restart squeezeslave you will see it starts to play again, so this is not a server issue (other than I suspect the streaming slimproto messages have changed slightly)

Alan - can you comment on what is likely to have changed in slimproto so the maintainer can look at this?

Nothing springs to mind. A log at levels player.source=info, network.protocol.slimproto=info might help illuminate the cause.

Hi,

I'm not able to determine whether its squeezeserver or squeezeslave that is causing the problem.  All I do know is that squeezeslave and 7.3x server worked fine together.  7.4x and squeezeslave don't work well.

Ralphy, the maintainer of squeezeslave, has since the original bug, issued newer versions of squeezeslave.  There are still problems.

http://forums.slimdevices.com/showthread.php?t=69338 

and 

http://vortexbox.org/forum/general/squeezeslave-and-74/?value=squeezeslave&type=1&include=1&search=1&ret=all

http://vortexbox.org/forum/help/change-squeezeslave-mac-address/?value=squeezeslave&type=1&include=1&search=1&ret=all
http://vortexbox.org/forum/beta/squeezeslave-0-9-95-beta-is-now-in-the-beta-repo/

I appreciate your continued efforts in this area.

Thanks,

same problem here. tried it with both 7.4.2. and the current trunk.
restarting squeezeslave helps but that's not a nice solution if you have a headless setup.

Created attachment 6457 [details]
Protocol changes diff between 7.3.4 and 7.4.2

Sorry my comments in my previous post were blank.

I've been looking into the suggestion that slimprotocol has changed between 7.3.4 and 7.4.2 but I'm unable to see anything obvious in the code.  Attached are diffs of these 4 files between said versions.

server/Slim/Networking/Slimproto.pm
server/Slim/Player/Squeezebox2.pm
server/Slim/Player/Player.pm
server/Slim/Player/Client.pm

Squeezebox2 is what the Squeezeslave.pm code is based.  There are no changes to Squeezeslave.pm between r28402 and r29885.

Is there something I'm missing?  If so, please comment as I'd like to fix the problem if it's truely an issue with Squeezeslave and slimprotocol.

Setting player.source=info and network.protocol.slimproto=info logging didn't show any obvious problems.

Thanks.

Ralph, the log output that I requested would still be the easiest way for me to comment usefully on this issue. Alan.

Created attachment 6460 [details]
SBS and squeezeslave log files

Alan,
 
I've been able to consistantly reproduce the hang by streaming even without the custom-convert.conf.  That should eliminate a few variables.

I'm running 7.4.2 r29879 from svn on winxp.
 
It appears that SBS isn't seeing the stat messages sent from squeezeslave while streaming and closes the connection as
 soon as I press stop from the classic skin.  This doesn't happen when playing music from the local hard drive. 
 
I was using a local ogg radio stream for my testing to rule out mp3/flac decoder issues.  I played the stream for about 15 seconds during each test. There are 4 logs files in the attached zip file.

server-info.log: SBS info slimproto log level
sslave-info.log: corresponding squeezeslave log
 
server-debug.log: SBS debug slimproto log level
sslave-debug.log: corresponding squeezeslave log
 
Both SBS logs include info player.source log levels as well.

I included the squeezeslave logs as they show squeezeslave sending STAT messages while playing the stream and responding to the strm-t from SBS.

Thanks for making time in your busy schdule to help with this.

Ah, the STAT-STMc after the strm-s is missing. See http://wiki.slimdevices.com/index.php/SlimProtoTCPProtocol

"STMc / Connect / srtm-s command received. Guaranteed to be the first response to an strm-s"

The server discards all STAT packets received after sending an strm-s until the correspoding STAT-STMc is received.

I'm sorry, that was a spurious observation as the Squeezeslave.pm module does not make that check in its statHandler method, and it is clear that the initial stat packets at the start of the stream are being acted upon.

From the server-debug log it looks like te player stops responding to packets for some reason:

[10-01-25 08:55:27.5193] Slim::Networking::Slimproto::_stat_handler (803) 00:17:31:7b:88:7b: STAT-STMt: fullness=0, output_fullness=539572, elapsed=15.030
[10-01-25 08:55:27.5199] Slim::Networking::Slimproto::_stat_handler (830) 00:17:31:7b:88:7b Squeezebox stream status:
        event_code:      STMt
        bytes_rec_H      0
        bytes_rec_L      19632128
        fullness:        0 (0%)
        bufferSize      3145728
        fullness         0
        bytes_received   19632128
        signal_strength: 65534
        jiffies:         2719149
        voltage:         0
[10-01-25 08:55:27.5203] Slim::Networking::Slimproto::_stat_handler (842) 
        output size:     3528000
        output fullness: 539572
        elapsed seconds: 15
[10-01-25 08:55:27.5208] Slim::Networking::Slimproto::_stat_handler (854) 
        elapsed milliseconds: 15030
        server timestamp:     0
[10-01-25 08:55:27.6477] Slim::Player::StreamingController::stop (1951) 00:17:31:7b:88:7b
[10-01-25 08:55:27.6482] Slim::Player::Squeezebox::stream (980) strm-q
[10-01-25 08:55:27.6486] Slim::Player::Squeezebox::stream (1025) sending strm frame of length: 24
[10-01-25 08:55:27.6490] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: strm, length: 24
[10-01-25 08:55:27.6497] Slim::Player::StreamingController::_Stop (607) Song queue is now 0
[10-01-25 08:55:27.6504] Slim::Player::StreamingController::_setPlayingState (2222) new playing state STOPPED
[10-01-25 08:55:27.6507] Slim::Player::StreamingController::_setStreamingState (2235) new streaming state IDLE
[10-01-25 08:55:27.6517] Slim::Player::Source::playmode (93) 00:17:31:7b:88:7b: Current playmode: stop
[10-01-25 08:55:27.6559] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320
[10-01-25 08:55:28.6689] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320
[10-01-25 08:55:28.7942] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320
[10-01-25 08:55:29.7957] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320
[10-01-25 08:55:30.7953] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320
[10-01-25 08:55:31.7953] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320
[10-01-25 08:55:32.0128] Slim::Networking::Slimproto::check_all_clients (211) Checking if 00:17:31:7b:88:7b is still alive
[10-01-25 08:55:32.0133] Slim::Player::Squeezebox::stream (980) strm-t
[10-01-25 08:55:32.0138] Slim::Player::Squeezebox::stream (1025) sending strm frame of length: 24
[10-01-25 08:55:32.0142] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: strm, length: 24
[10-01-25 08:55:32.7953] Slim::Player::Squeezebox::sendFrame (1104) sending squeezebox frame: vfdc, length: 320

Nothing is heard after the STAT-STMt at 10-01-25 08:55:27.5193

Looking at the ss log we see:

proto_stat: code=STMt decoder_buffer_size=3145728 decoder_buffer_fullness=0 rbytes_high=0 rbytes_low=19623936 output_buffer_size=3528000 output_buffer_fullness=525068 elapsed_seconds=14 elapsed_milliseconds=14524 server_timestamp=1707342283
proto_send: cmd=STAT len=55
DONE strm cmd t
proto_stat: code=STMt decoder_buffer_size=3145728 decoder_buffer_fullness=0 rbytes_high=0 rbytes_low=19632128 output_buffer_size=3528000 output_buffer_fullness=539572 elapsed_seconds=15 elapsed_milliseconds=15030 server_timestamp=0
proto_send: cmd=STAT len=55
proto_recv: cmd=strm len=30
strm cmd q strm.replay_gain:0 
slimaudio_decoder_vorbis_process: end
decoder_thread: STREAM_PLAY (before STMd) previous state: 1
decoder_thread: STREAM_STOP previous state: 1
decoder_thread: STREAM_STOPPED first_time:0
http_recv: (2) n=-1 WSAGetLastError=(10054)
http_thread state 1
proto_send: cmd=DSCO len=1
http_thread state 2
proto_stat: code=STMf decoder_buffer_size=3145728 decoder_buffer_fullness=0 rbytes_high=0 rbytes_low=19632128 output_buffer_size=3528000 output_buffer_fullness=0 elapsed_seconds=0 elapsed_milliseconds=0 server_timestamp=0
proto_send: cmd=STAT len=55
proto_send: (1) n=-1 WSAGetLastError=(10053)
proto_close: state 3
Stopping audio because of disconnection.
audio_stop early out.

It gets confused by the sequence of packets from SbS. It sends a DSCO packet and seems to consider that the slimproto connection is now closed but it has not actually closed the slimproto TCP connection.
 
But the real question is why does it get confused?

Created attachment 6477 [details]
Output from gdb 'thread apply all bt full'

I've attached the output from the gdb command 'thread apply all bt full' for two frozen squeezeslave instances caused by remote streaming from 7.4.2.  I'm hoping someone with more experience with resolving deadlock threads issues can help.  

The source code line references are from squeezeslave revision 127.

The deadlock does NOT occur when playing local music files.

Alan,

I've been looking at this issue again today and I find it strange that local files stream without issue but not remote streams, even the first time a remote stream is started squeezeslave plays the stream without issue.

It breaks when the server sends a strm-q  STOP command while the first remote stream is playing and squeezeslave hangs. According to the server.log file no heartbeat has been received since the stream was started ~15 seconds ago and resets the connection.

Could the server be ignoring the status/heartbeat messages? Although an STMc is not required by SqueezeSlave.pm does the remote streaming code/state machine still require it?

If you look around line 96 of server-info.log, if I'm reading it correctly, you see that squeezeslave is responding to strm-t messages as the output_fullness value is changing.

The squeezeslave log file shows it responding to status messages as well as returning the latency timestamp.  You can see this starting at line 285 of sslave-info.log, the play time in seconds is tracking properly as well.  It looks like the hang is caused by the server resetting the connection "http_recv: (2) n=-1 WSAGetLastError=(10054)" which squeezeslave fails to handle properly and needs to be fixed.  But it doesn't explain why the server decides to forget the player.

I've done the same test on 7.3.4 and compared the logs of both the server and squeezeslave to the results of the above test and other than timestamps and buffer fullness levels I can see no differences in the logs.

Thanks for any further assistance you can provide.

Ralph.

I should have stated that the only difference between the 7.3.4 and 7.4.2 logs is the connection is closed in 7.3.4 "http_recv: (2) n=0 WSAGetLastError=(0)" as opposed to reset in 7.4.2.

I've determined that r28009 applied by Adrian to fix bug 10085 causes squeezeslave to hang.

I tried these revisions of 7.4 to be sure.

r23958 good
r27123 good
r27893 good
r27983 good
r28008 good
r28009 bad
r28034 bad
r28086 bad
r28282 bad
r28672 bad

$ svn -r28009 log
------------------------------------------------------------------------
r28009 | adrian | 2009-08-03 09:38:28 -0400 (Mon, 03 Aug 2009) | 3 lines
 
Bug: 10085
Description: change fix for this bug to check if the callback is for the active streaming socket rather than just a connected socket.  When moving from one track using a pipeline to another it is possible for the new streaming connection to be created before the old one is closed, so make sure we only kill timers if we are the active socket.

$ svn -r28008:28009 diff
Index: Slim/Web/HTTP.pm
===================================================================
--- Slim/Web/HTTP.pm    (revision 28008)
+++ Slim/Web/HTTP.pm    (revision 28009)
@@ -2176,11 +2176,11 @@
        my $client     = shift;
        my $httpClient = shift;

-       if ( $httpClient->connected() ) {
-
+       if ( $httpClient == $client->streamingsocket() ) {
+
                # Bug 10085 - This might be a callback for an old connection
                # which we decided to close after establishing the timer, so
-               # only kill the timer if we were called for an active connection;
+               # only kill the timer if we were called for the active streaming connection;
                # otherwise we might kill the timer related to the next connection too.
                Slim::Utils::Timers::killTimers($client, \&tryStreamingLater);

(In reply to comment #19)
> I've determined that r28009 applied by Adrian to fix bug 10085 causes
> squeezeslave to hang.

Confirm that reverting this also works here (squeezeboxserver-7.4.1 on gentoo, squeezeslave-116 built from source ~end of Dec 09). 

Before this changing a streaming radio station caused the remote squeezeslave to lock up - now I can flick between stations.

Thanks!

Paul

Looks like with the current server code we don't actively close the old streaming socket from the server end if it relied on tryStreamingLater.  I think the server code should do this, so the server should probably be changed to:

--- Slim/Web/HTTP.pm    (revision 30371)
+++ Slim/Web/HTTP.pm    (working copy)
@@ -2214,9 +2214,10 @@
                # only kill the timer if we were called for the active streaming connection;
                # otherwise we might kill the timer related to the next connection too.
                Slim::Utils::Timers::killTimers($client, \&tryStreamingLater);
-
-               Slim::Networking::Select::addWrite($httpClient, \&sendStreamingResponse, 1);
        }
+
+       # Always call sendStreamingResponse so we ensure the socket gets closed
+       Slim::Networking::Select::addWrite($httpClient, \&sendStreamingResponse, 1);
 }

However I suspect the reason why we only see this with squeezeplay is that other players actively close the streaming socket from their end.  When you get an strm-s could you actively close the connection from the squeezeplay end?

Alan - I suspect we are too late to put the above into 7.5, but do you agree with the above?

So the reason squeezeslave locks up is that it is fetching data from the http streaming socket in blocking mode, so the thread which calls recv blocks when the server stops sending data.  With the change to the server, the socket is closed and recv returns an error allowing the thread to continue.

We should probably patch squeezeslave to us non blocking calls to fetch data from the socket so that it can transition to the stopped state and close the socket under slimproto control rather than waiting for more data or the socket to be closed.  I'll have a look and post a patch if I get it working better.

Ralph, try something like the following - this seems to fix it on the player end for me.  Just allow the http thread to keep spinning at a low rate if there is nothing received from the socket.

--- src/slimaudio/slimaudio_http.c      (revision 129)
+++ src/slimaudio/slimaudio_http.c      (working copy)
@@ -293,7 +293,19 @@
 
 static void http_recv(slimaudio_t *audio) {
        char buf[AUDIO_CHUNK_SIZE];
+       struct timeval timeOut; 
+       fd_set fdread;
 
+       timeOut.tv_sec  = 0; 
+       timeOut.tv_usec = 100*1000; /* wait for up to 100ms */
+
+       FD_ZERO(&fdread); 
+       FD_SET(audio->streamfd, &fdread);  
+
+       if (select(audio->streamfd + 1, &fdread, NULL, &fdread, &timeOut) == 0) {
+               return;
+       }
+
        int n = recv(audio->streamfd, buf, AUDIO_CHUNK_SIZE, 0);
 
        /* n == 0 http stream closed by server */

Adrian,

Thank you for taking the time to create a squeezeslave patch to fix the problem with the current server versions.

My initial testing of your fix is working well.

I'll report back once I've had a few days using it.

Ralph.

Adrian,

I tested your suggested server side change in comment 21 using 7.4r30377 against squeezeslave r95 and r116 mentioned in the bug and both work flawlessly.  Hopefully the change eventually makes it into the code.

The non-blocking change you provided for squeezeslave fixes the problem as well.  Revision 133 includes the fix and I've released test builds for Win32 and OSX.  I listened to internet streams most of the day yesterday without issue and would consider the problem fixed.

You mentioned squeezeplay in a couple of your comments, not sure if that was a typo or if you've been seeing a similiar issue with squeezeplay as well.

Thanks again for your help.

Ralphy.

Ralphy, sorry squeezeplay was a typo - this can definately cope with the current server operation.  My comments were about squeezeslave.  If the patch is ok then I think we have a solution for the short term.  I propose we do at the server patch though but not for 7.5.

Too bad I didn't figure out what change was causing the hang earlier.  It would have been great to get the server side change in in time for the 7.5 code freeze.

You should be able to close this bug, unless we need confirmation from the reporter, Andrew.

Adrian,

Now that the 7.6 branch has been created, would it be possible for you to commit the Slim/Web/HTTP.pm patch from comment #21?

Thanks,

Ralphy.

I was hoping Alan would review comment #21 first, but I agree it should go into the server.

I still think you need to protect against blocking in squeezeslave waiting for data as there could be other cases where the stream stalls.  So I suggest you keep the workaround, but agree we should get this into the server.

Thanks Adrian.

I have no intensions of removing the non-blocking fix from squeezeslave.

Would just like to have the complete fix applied as well.

Ralphy.

Adrian, yes I think that should be safe. It will cause sendStreamingResponse() which will detect that $httpClient != $client->streamingsocket() and so close the socket.

 == Auto-comment from SVN commit #30500 to the slim repo by adrian ==
 == http://svn.slimdevices.com/slim?view=revision&revision=30500 ==

Bug: 14740
Description: actively close old streaming sockets when using tryStreamingLater